Yes, but did you have the same workload when you upgraded to 9.3 as you do today?

The workload is very similar. We upgraded from 9.1 to 9.3 only two months ago, and our usage statistics have not changed much. There were no "remaining connection slots are reserved for non-replication superuser connections" messages in the weeks after the 9.3 upgrade.

BTW, something else to be aware of: because you essentially re-loaded all your data in a single transaction, that means that a: you'll be doing a lot of hint bit updates until all data has been read a second time, and b: a lot of this data will come up for freezing at around the same time, creating a big chunk of work for autovacuum. That's caused problems for me in the past, though that was on a database that had a pretty high workload.

We run "VACUUM ALL" every night and although that gave a bit more CPU and I/O but nothing major.

When the problem occurs, the symptoms are:
- spike to a very high load average (= CPU usage)
- messages about long waits on ExclusiveLock on extension appear
- remaining connection slots are reserved (with corresponding end user impact)

An example of a message with 1 second wait duration and a lot of waiting queries:

process 667 still waiting for ExclusiveLock on extension of relation 1249 of database 16406 after 1005.226 ms","Process holding the lock: 36279. Wait queue: 36725, 36405, 36511, 36721, 36280, 36048, 36566, 36636, 36466, 36734, 36723, 36621, 36423, 36931, 36720, 36429, 35500, 36735, 37015, 36717, 36938, 36870, 36732, 36587, 36869, 36285, 36573, 37101, 36937, 36414, 36834, 37105, 36867, 36724, 36991, 37102, 36882, 36802, 37163, 39964, 39723, 40044, 39821, 40150, 40218, 40203, 40054, 40060, 40173, 40091, 40174, 40058, 40658, 40370, 40177, 40920, 41085, 41103, 41117, 41154, 41161, 41066, 41053, 41380, 40661, 40632, 40698, 41242, 40681, 41174, 41328, 41075, 41245, 41326, 41523, 41153, 41170, 40543, 41314, 41526, 41490, 41157, 41353, 41472, 41730, 41546, 45087, 41535, 41474, 41362, 41450, 41948, 41929, 41459, 41508, 42117, 42127, 41950, 41922, 42414, 41939, 42565, 42643, 42242, 41796, 42324, 42358, 42411, 42487, 41758, 42120, 42570, 41820, 41925, 43356, 43381, 43360, 43351, 43364, 42336, 42871, 43007, 42455, 43363, 42287, 43336, 42652, 42803, 43567, 43706, 43795, 43630, 43716, 43810, 43596, 43061, 43954, 44014, 43377, 43366, 43825, 43454, 43840, 43582, 43839, 44009, 43842, 43693, 44320, 43824, 43456, 43852, 43863, 44708, 43848, 44255, 44587, 44936, 44915, 44759, 44700, 44948, 45051, 44808, 45189, 45137, 45037, 45303, 45294, 45710, 45711, 45755, 45660, 45120, 45576, 46221, 46125, 46703, 46512, 46399, 46684, 46762, 46373, 46929, 46443, 46817, 46858, 47017, 46886, 46805, 46890, 47593, 47548, 47272, 47454, 47906, 47462, 47801, 47939, 47994, 48098, 48363, 47815, 48393, 48250, 48213, 48470, 48408, 48509, 48499, 48115, 48448, 48877, 461, 560, 637, 48902, 641, 49019, 667, 877, 1306, 1070, 1265.",,,,"SQL statement ""CREATE TEMPORARY TABLE

An example of a message with 140 second wait duration:

process 27173 acquired ExclusiveLock on extension of relation 16787 of database 16406 after 138522.699 ms",,,,,"SQL statement ""INSERT INTO

There are about 50 queries a second, so a 10 second lock will exhaust the number of available connections.

We keep sar logs, and they show an unusual amount of pgscand/s and pgsteal/s around the time of the problem:

07:25:01 PM pgpgin/s pgpgout/s fault/s majflt/s pgfree/s pgscank/s pgscand/s pgsteal/s %vmeff 08:25:01 PM 29.93 1069.13 393727.33 0.00 170655.03 0.00 90.20 90.20 100.00 08:26:01 PM 20.14 1325.55 388751.51 0.00 157188.40 0.00 315.81 315.81 100.00 08:27:02 PM 59.33 1215.97 612453.98 0.00 271483.71 0.00 180.40 180.40 100.00 08:28:01 PM 43.28 1881.71 473067.50 0.00 236778.10 0.00 114.87 114.87 100.00 08:29:01 PM 23.49 665.73 406865.61 0.00 213178.17 0.00 293.11 293.11 100.00 08:30:01 PM 31.39 1317.51 448565.03 0.02 193320.76 0.00 225.88 225.83 99.98
-- Problem starts here
08:31:02 PM 21.16 1499.32 468467.44 0.10 211767.21 0.00 4311.87 4311.84 100.00 08:32:01 PM 10.19 648.87 261067.16 0.05 167231.84 0.00 1071.01 1070.98 100.00 08:33:01 PM 63.59 950.94 422101.19 0.22 242284.12 0.00 1243.37 1243.34 100.00
-- Problem ends here
08:34:01 PM 24.97 1321.61 412294.87 0.00 273734.03 0.00 0.00 0.00 0.00 08:35:01 PM 11.60 1094.22 353741.41 0.00 238541.73 0.00 0.00 0.00 0.00 08:36:01 PM 39.22 976.60 368450.80 0.10 240632.57 0.00 0.00 0.00 0.00 08:37:01 PM 19.83 967.31 320415.39 0.00 217557.42 0.00 0.00 0.00 0.00 08:38:01 PM 15.68 1884.09 301785.58 0.00 200274.51 0.00 0.00 0.00 0.00 08:39:01 PM 62.61 858.31 487099.01 0.00 330130.65 0.00 0.00 0.00 0.0

pgscand/s = Number of pages scanned directly per second.
pgsteal/s = Number of pages the system has reclaimed from cache (pagecache and swapcache) per second to satisfy its memory demands.

Could the pgscand and pgsteal numbers provide a hint? They're sometimes zero for more than half an hour, so they don't seem related to checkpoints.

Kind regards,
Andomar



--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

Reply via email to