Re: Checkpoint Tuning Question

> 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