> However, the latest report says that he > managed that, and yet there's still a one-or-two-second transient of > some sort. I'm wondering what's causing that. If it were at the *end* > of the checkpoint, it might be the disk again (failing to handle a bunch > of fsyncs, perhaps). But if it really is at the *start* then there's > something else odd happening. > > regards, tom lane > Log output during heavy load - checkpoint logging on, and slow query logging on for queries that take longer than 1 second. Blank space inserted to show interesting bits.... Almost all of the slow query log messages are logged within about 3 seconds of the checkpoint starting message. LOG: checkpoint starting: xlog LOG: duration: 1101.419 ms execute <unnamed>: select dynamichos0_.ethernetmacaddr as ethernet1_0_, dynamichos0_.ipaddr as ipaddr0_, dynamichos0_.cpemac as cpemac0_, dynamichos0_.last_updated as last3_0_, dynamichos0_.leasetime as leasetime0_, dynamichos0_.regtime as regtime0_ from iphost dynamichos0_, cpe cpe1_ where dynamichos0_.cpemac=cpe1_.cpemac and 1=1 and dynamichos0_.ethernetmacaddr=$1 and dynamichos0_.cpemac=$2 and cpe1_.regBaseId=$3 and dynamichos0_.ipaddr<>$4 DETAIL: parameters: $1 = '01:01:01:56:01:7F', $2 = '00:55:00:82', $3 = '01:01:01:56', $4 = '000.000.000.000' LOG: duration: 1101.422 ms execute <unnamed>: insert into iphost (cpemac, last_updated, leasetime, regtime, ethernetmacaddr, ipaddr) values ($1, $2, $3, $4, $5, $6) DETAIL: parameters: $1 = '01:AA:00:A0', $2 = '2009-07-08 15:33:20.673', $3 = '2009-07-08 21:06:40.67', $4 = '2009-07-08 15:33:20.67', $5 = '01:01:02:AB:01:9D', $6 = '2.171.156.0' <snip about 200 lines of similar messages> LOG: duration: 1501.905 ms execute <unnamed>: select dynamichos0_.ethernetmacaddr as ethernet1_0_, dynamichos0_.ipaddr as ipaddr0_, dynamichos0_.cpemac as cpemac0_, dynamichos0_.last_updated as last3_0_, dynamichos0_.leasetime as leasetime0_, dynamichos0_.regtime as regtime0_ from iphost dynamichos0_, cpe cpe1_ where dynamichos0_.cpemac=cpe1_.cpemac and 1=1 and dynamichos0_.ethernetmacaddr=$1 and dynamichos0_.cpemac=$2 and cpe1_.regBaseId=$3 and dynamichos0_.ipaddr<>$4 DETAIL: parameters: $1 = '01:01:01:C3:01:8B', $2 = '00:C2:00:8E', $3 = '01:01:01:C3', $4 = '000.000.000.000' LOG: checkpoint complete: wrote 9975 buffers (77.9%); 0 transaction log file(s) added, 0 removed, 15 recycled; write=156.576 s, sync=0.065 s, total=156.662 s LOG: checkpoint starting: xlog LOG: duration: 1104.780 ms execute <unnamed>: delete from iphost where ethernetmacaddr=$1 and ipaddr=$2 and last_updated=$3 DETAIL: parameters: $1 = '01:01:01:33:01:AA', $2 = '1.50.169.0', $3 = '2009-07-08 15:32:57.131' LOG: duration: 1106.499 ms execute <unnamed>: select cpe0_.cpemac as cpemac2_0_, cpe0_.changeTime as changeTime2_0_, cpe0_.comment as comment2_0_, cpe0_.configuration as configur4_2_0_, cpe0_.cpeconfigid as cpeconf17_2_0_, cpe0_.cpefilterid as cpefilt18_2_0_, cpe0_.endTime as endTime2_0_, cpe0_.ispId as ispId2_0_, cpe0_.last_updated as last7_2_0_, cpe0_.reglocationid as regloca19_2_0_, cpe0_.modelId as modelId2_0_, cpe0_.numberOfHosts as numberOf9_2_0_, cpe0_.regBaseId as regBaseId2_0_, cpe0_.regTime as regTime2_0_, cpe0_.roamAllowed as roamAll12_2_0_, cpe0_.serialNumber as serialN13_2_0_, cpe0_.slaid as slaid2_0_, cpe0_.enable as enable2_0_, cpe0_.staticip as staticip2_0_, cpe0_.subscriberid as subscri21_2_0_, cpe0_.swVersion as swVersion2_0_, cpe0_.vlanid as vlanid2_0_, cpe0_.voipid as voipid2_0_ from cpe cpe0_ where cpe0_.cpemac=$1 DETAIL: parameters: $1 = '00:84:00:37' <snip about 300 lines of similar messages> LOG: duration: 1205.828 ms execute <unnamed>: insert into iphost (cpemac, last_updated, leasetime, regtime, ethernetmacaddr, ipaddr) values ($1, $2, $3, $4, $5, $6) DETAIL: parameters: $1 = '02:31:00:25', $2 = '2009-07-08 15:39:53.718', $3 = '2009-07-08 21:13:13.715', $4 = '2009-07-08 15:39:53.715', $5 = '01:01:03:32:01:22', $6 = '3.51.33.0' LOG: duration: 1203.287 ms execute <unnamed>: insert into iphost (cpemac, last_updated, leasetime, regtime, ethernetmacaddr, ipaddr) values ($1, $2, $3, $4, $5, $6) DETAIL: parameters: $1 = '03:47:00:81', $2 = '2009-07-08 15:39:53.72', $3 = '2009-07-08 21:13:13.717', $4 = '2009-07-08 15:39:53.717', $5 = '01:01:04:48:01:7E', $6 = '4.74.125.0' LOG: duration: 1201.480 ms execute <unnamed>: insert into iphost (cpemac, last_updated, leasetime, regtime, ethernetmacaddr, ipaddr) values ($1, $2, $3, $4, $5, $6) DETAIL: parameters: $1 = '01:12:00:7F', $2 = '2009-07-08 15:39:53.725', $3 = '2009-07-08 21:13:13.721', $4 = '2009-07-08 15:39:53.721', $5 = '01:01:02:13:01:7C', $6 = '2.19.123.0' LOG: checkpoint complete: wrote 9794 buffers (76.5%); 0 transaction log file(s) added, 0 removed, 15 recycled; write=148.084 s, sync=0.062 s, total=148.172 s -- Sent via pgsql-general mailing list (pgsql-general@xxxxxxxxxxxxxx) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-general
