Re: WAL recycling, ext3, Linux 2.4.18

At 11:57 AM 7/8/2002, Tom Lane wrote:
>Doug Fields <dfields-pg-general(at)pexicom(dot)com> writes:
> > I'm still trying to track down my very odd periodic pauses/hangs in
> > PostgreSQL 7.2.1.
> > I've localized it to what seems to be the "recycled transaction log file"
> > lines in the log file. Whenever this happens, a whole bunch of queries
> > which were "on hold" (just sitting there, as can be seen in
> > pg_stat_activity, when they usually execute in fractions of a second) come
> > back to life and finish very quickly.
>
>Hm. That would be from the tail end of a checkpoint operation. If you
>do a CHECKPOINT command manually, do you get a similar hangup?

In fact, yes. (I never did a CHECKPOINT ever before now.) It took less time
(probably because I did it around half way through the 6.5-minute WAL
recycling period), but had almost identical effects. pg_stat_activity
showed a whole bunch of queries stacked up, and vmstat exhibited the same
pathology: the other postgres processes blocked during the checkpoint (it's
pretty plain in the vmstat output below).

procs memory swap io system
cpu
r b w swpd free buff cache si so bi bo in cs us
sy id
0 0 0 0 3851828 121732
3913552 0 0 2 79 56 62 49 2 49
1 0 0 0 3850724 121732
3913576 0 0 0 1171 214 1023 4 0 95
1 0 0 0 3851544 121732
3913576 0 0 0 266 179 148 1 0 99
0 0 0 0 3851780 121732
3913600 0 0 0 1407 266 364 4 1 95
0 2 1 0 3843020 121732
3913616 0 0 0 4182 195 186 2 4 94
0 2 3 0 3841608 121732
3913616 0 0 0 2722 197 191 0 1 99
0 2 3 0 3840984 121732
3913616 0 0 0 2774 232 298 1 1 99
0 2 3 0 3840056 121732
3913616 0 0 0 2739 200 204 1 1 99
0 2 3 0 3839280 121732
3913616 0 0 0 1634 183 201 1 0 99
0 2 4 0 3839424 121732
3913616 0 0 0 4098 202 143 0 1 99
0 2 4 0 3837672 121732
3913616 0 0 0 2710 194 170 1 1 99
0 2 3 0 3836992 121732
3913616 0 0 0 2139 156 82 0 0 99
0 2 4 0 3827844 121732
3913632 0 0 0 5362 170 3260 3 1 95
0 2 4 0 3828592 121732
3913632 0 0 0 2134 143 53 0 1 99
1 1 0 0 3830892 121744
3913668 0 0 0 4926 152 6087 8 3 89
0 0 0 0 3850360 121744 3913772 0 0 0 7851 610
16106 61 5 34
0 0 0 0 3850360 121744
3913772 0 0 0 20 189 284 1 0 99
0 0 0 0 3850360 121744
3913772 0 0 0 14 147 157 0 0 100

>What are the stuck queries doing exactly? Can you attach to a few of the
>stuck backends with gdb and get stack traces?

The stuck queries are of the following nature, typically either:

1) UPDATE x SET somedate=now() WHERE primarykey IN (1,2,3,4...300 to 450 IDs)
2) DELETE FROM x WHERE key1 = 1 AND key2 IN (1,2,3,4...300 to 450 IDs)

In my pg_stats display below you can see some of them.

Here is a stack trace. I did "where" about every second during the "pause"
and received the same stack trace. This is on PID 3456 per the
pg_stat_activity listing below. After things clear up, I also did a stack
trace; it's blocked on recv, presumably waiting for more commands to come
down the socket. (I tried a few other PIDs with similar stack traces, all
stuck on the semop call.)

(gdb) c
Continuing.

Program received signal SIGINT, Interrupt.
0x4028913f in semop () from /lib/libc.so.6
(gdb) where
#0 0x4028913f in semop () from /lib/libc.so.6
#1 0x08106dec in IpcSemaphoreLock ()
#2 0x0810bce1 in LWLockAcquire ()
#3 0x0808433b in XLogInsert ()
#4 0x08079033 in _bt_doinsert ()
#5 0x08078ea9 in _bt_doinsert ()
#6 0x080786ed in _bt_doinsert ()
#7 0x0807be9d in btinsert ()
#8 0x08152822 in OidFunctionCall5 ()
#9 0x08077cf8 in index_insert ()
#10 0x080c674a in ExecInsertIndexTuples ()
#11 0x080c373e in ExecutorEnd ()
#12 0x080c3374 in ExecutorEnd ()
#13 0x080c2797 in ExecutorRun ()
#14 0x081104de in ProcessQuery ()
#15 0x0810ed70 in pg_exec_query_string ()
#16 0x0810fd5e in PostgresMain ()
#17 0x080f6d4e in ClosePostmasterPorts ()
#18 0x080f669f in ClosePostmasterPorts ()
#19 0x080f5882 in PostmasterMain ()
#20 0x080f5391 in PostmasterMain ()
#21 0x080d4e18 in main ()
#22 0x401d114f in __libc_start_main () from /lib/libc.so.6
(gdb) c
Continuing.

And then later...

(gdb) c
Continuing.

Program received signal SIGINT, Interrupt.
0x402887f2 in recv () from /lib/libc.so.6
(gdb) where
#0 0x402887f2 in recv () from /lib/libc.so.6
#1 0x080d42bc in StreamClose ()
#2 0x080d430d in pq_getbyte ()
#3 0x0810e7c8 in HandleFunctionRequest ()
#4 0x0810e837 in HandleFunctionRequest ()
#5 0x0810fc5e in PostgresMain ()
#6 0x080f6d4e in ClosePostmasterPorts ()
#7 0x080f669f in ClosePostmasterPorts ()
#8 0x080f5882 in PostmasterMain ()
#9 0x080f5391 in PostmasterMain ()
#10 0x080d4e18 in main ()
#11 0x401d114f in __libc_start_main () from /lib/libc.so.6
(gdb) c
Continuing.

> > 1) Is there any known bad interactions with ext3fs and PostgreSQL?
>
>Dunno. The CHECKPOINT would probably create a significant number of
>disk write requests, followed by a sync() request. If that could
>monopolize an ext3 filesystem for a long time, perhaps that would
>explain your problem. But I haven't heard similar complaints before.
>
>What do you have shared_buffers set to?

pexicast_lg=# show shared_buffers;
NOTICE: shared_buffers is 65536
SHOW VARIABLE

I believe this is about 512 megs. I have 8 gigs RAM on this server and
tried 65536 and before it 32768. Either one seems to work fine - I didn't
notice any significant performance difference yet between them.

See below for pg_stat_activity...

I appreciate the help!

Cheers,

Doug

pexicast_lg=# select * from pg_stat_activity where datname='pexicast_lg';
select now();
datid | datname | procpid | usesysid | usename
|
current_query

---------+-------------+---------+----------+---------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
3926366 | pexicast_lg | 3393 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(463196,463216,463236,463256,463276,463296,461176,461196,461216,461236,461256,461276,461296,461316,461336,461356,461376,461396,461416,461436,461456,461476,461496,461516,461536,461556,461576,46
3926366 | pexicast_lg | 3412 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(425066,425086,425106,425126,425146,425166,425186,425206,425226,425246,425266,425286,425306,425326,425346,425366,425386,425406,425426,425446,425466,425486,425506,425526,425546,425566,425586,42
3926366 | pexicast_lg | 3443 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(442093,442113,442133,442153,442173,442193,442213,442233,442253,442273,442293,442313,442333,442353,442373,442393,442413,442433,442453,442473,442493,442513,442533,442553,442573,442593,442613,44
3926366 | pexicast_lg | 3444 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(438107,438127,438147,438167,438187,438207,438227,438247,436147,436167,436187,436207,436227,436247,436267,436287,436307,436327,436347,436367,436387,436407,436427,436447,436467,436487,436507,43
3926366 | pexicast_lg | 3446 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(429470,429490,429510,429530,429550,429570,429590,429610,429630,429650,429670,429690,429710,429730,429750,429770,429790,429810,429830,429850,429870,429890,429910,429930,427830,427850,427870,42
3926366 | pexicast_lg | 3447 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(463658,463678,463698,463718,463738,463758,463778,463798,463818,463838,463858,463878,463898,463918,460378,461838,461858,461878,461898,461918,461938,461958,461978,461998,462018,462038,462058,46
3926366 | pexicast_lg | 3448 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(407502,407522,407542,407562,407582,407602,407622,407642,407662,407682,407702,407722,407742,407762,407782,407802,407822,407842,407862,407882,405802,405822,405842,405862,405882,405902,405922,40
3926366 | pexicast_lg | 3449 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(475717,475737,475757,475777,475797,475817,475837,475857,475877,475897,475917,475937,475957,475977,475997,476017,476037,476057,476077,476097,476117,476137,476157,474077,474097,474117,474137,47
3926366 | pexicast_lg | 3450 | 100 | tomcat | <IDLE>
3926366 | pexicast_lg | 3451 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(438472,438492,438512,438532,438552,438572,438592,438612,438632,438652,438672,436572,436592,436612,436632,436652,436672,436692,436712,436732,436752,436772,436792,436812,436832,436852,436872,43
3926366 | pexicast_lg | 3452 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(415401,415421,415441,415461,415481,415501,415521,415541,415561,415581,415601,415621,415641,415661,415681,413581,413601,413621,413641,413661,413681,413701,413721,413741,413761,413781,413801,41
3926366 | pexicast_lg | 3453 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(442908,442928,442948,442968,440868,440888,440908,440928,440948,440968,440988,441008,441028,441048,441068,441088,441108,441128,441148,441168,441188,441208,441228,441248,441268,441288,441308,44
3926366 | pexicast_lg | 3454 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(410524,410544,410564,410584,410604,410624,410644,410664,410684,410704,410724,410744,408644,408664,408684,408704,408724,408744,408764,408784,408804,408824,408844,408864,408884,408904,408924,40
3926366 | pexicast_lg | 3455 | 100 | tomcat | <IDLE>
3926366 | pexicast_lg | 3456 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(451115,451135,451155,451175,451195,451215,451235,451255,451275,451295,451315,451335,451355,451375,451395,451415,451435,451455,451475,451495,451515,451535,451555,449475,449495,449515,449535,44
3926366 | pexicast_lg | 3457 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(408325,408345,408365,408385,408405,408425,408445,408465,408485,408505,408525,408545,406465,406485,406505,406525,406545,406565,406585,406605,406625,406645,406665,406685,406705,406725,406745,40
3926366 | pexicast_lg | 3458 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(397080,397100,397120,397140,397160,397180,397200,397220,397240,397260,397280,397300,397320,397340,397360,397380,397400,397420,397440,397460,397480,397500,397520,397540,397560,397580,397600,39
3926366 | pexicast_lg | 3459 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(476459,476479,476499,476519,476539,476559,476579,476599,476619,476639,476659,476679,476699,476719,476739,476759,474659,474679,474699,474719,474739,474759,474779,474799,474819,474839,474859,47
3926366 | pexicast_lg | 3460 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(411003,411023,411043,411063,411083,411103,411123,411143,411163,411183,411203,411223,411243,411263,411283,411303,411323,411343,411363,411383,411403,411423,411443,411463,411483,411503,411523,41
3926366 | pexicast_lg | 3461 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(432589,432609,432629,432649,432669,432689,432709,432729,432749,432769,432789,432809,432829,432849,432869,432889,432909,430809,430829,430849,430869,430889,430909,430929,430949,430969,430989,43
3926366 | pexicast_lg | 3462 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(470654,470674,470694,470714,470734,470754,470774,470794,470814,470834,470854,470874,470894,470914,470934,470954,470974,470994,471014,471034,471054,471074,471094,471114,471134,471154,471174,47
3926366 | pexicast_lg | 3497 | 100 | tomcat | UPDATE
list_entries SET last_mail=now() WHERE list_entry_id IN
(440551,440571,440591,440611,440631,440651,440671,440691,440711,440731,440751,440771,440791,440811,440831,440851,440871,440891,440911,440931,440951,440971,440991,441011,441031,441051,441071,44
3926366 | pexicast_lg | 4235 | 101 | dfields | <IDLE>
(23 rows)