Re: Linux/PostgreSQL scalability issue - problem with 8 cores

Hi Tom,

> Strange. The best idea that comes to mind is to add some debugging
> code to SendSharedInvalidMessage to log the content of each message
> that's sent out. That would at least tell us *what* is going into
> the queue, even if not directly *why*.

we've patched postgresql and run one of our plpgsql complex procedures.
There are many of sinval messages - log output is below.

What does it mean?

Thanks,

Kuba

LOG: sending inval msg 30 0 26 13 30036 4294936593
LOG: sending inval msg 29 0 26 13 30036 337030170
LOG: sending inval msg 30 0 25 46 30036 4294936593
LOG: sending inval msg 29 0 25 46 30036 337030170
LOG: sending inval msg 30 0 26 13 30036 4294936593
LOG: sending inval msg 29 0 26 13 30036 337030170
LOG: sending inval msg 30 0 25 45 30036 4294936595
LOG: sending inval msg 29 0 25 45 30036 2019111801
LOG: sending inval msg 30 0 26 11 30036 4294936595
LOG: sending inval msg 29 0 26 11 30036 2019111801
LOG: sending inval msg 30 0 25 44 30036 4294936597
LOG: sending inval msg 29 0 25 44 30036 3703878920
LOG: sending inval msg 30 0 26 10 30036 4294936597
LOG: sending inval msg 29 0 26 10 30036 3703878920
LOG: sending inval msg 30 0 26 9 30036 4294936616
LOG: sending inval msg 29 0 26 9 30036 3527122063
LOG: sending inval msg 30 0 25 43 30036 4294936616
LOG: sending inval msg 29 0 25 43 30036 3527122063
LOG: sending inval msg 30 0 26 9 30036 4294936616
LOG: sending inval msg 29 0 26 9 30036 3527122063
LOG: sending inval msg 30 0 25 41 30036 4294936618
LOG: sending inval msg 29 0 25 41 30036 2126866956
LOG: sending inval msg 30 0 26 7 30036 4294936618
LOG: sending inval msg 29 0 26 7 30036 2126866956
LOG: sending inval msg 30 0 25 40 30036 4294936620
LOG: sending inval msg 29 0 25 40 30036 1941919314
LOG: sending inval msg 30 0 26 5 30036 4294936620
LOG: sending inval msg 29 0 26 5 30036 1941919314
LOG: sending inval msg 30 0 26 4 30036 4294936633
LOG: sending inval msg 29 0 26 4 30036 544523647
LOG: sending inval msg 30 0 25 39 30036 4294936633
LOG: sending inval msg 29 0 25 39 30036 544523647
LOG: sending inval msg 30 0 26 4 30036 4294936633
LOG: sending inval msg 29 0 26 4 30036 544523647
LOG: sending inval msg 30 0 25 38 30036 4294936635
LOG: sending inval msg 29 0 25 38 30036 2557582018
LOG: sending inval msg 30 0 26 3 30036 4294936635
LOG: sending inval msg 29 0 26 3 30036 2557582018
LOG: sending inval msg 30 0 25 37 30036 4294936637
LOG: sending inval msg 29 0 25 37 30036 2207280630
LOG: sending inval msg 30 0 26 2 30036 4294936637
LOG: sending inval msg 29 0 26 2 30036 2207280630
LOG: sending inval msg 30 0 26 1 30036 4294936669
LOG: sending inval msg 29 0 26 1 30036 1310188568
LOG: sending inval msg 30 0 25 36 30036 4294936669
LOG: sending inval msg 29 0 25 36 30036 1310188568
LOG: sending inval msg 30 0 26 1 30036 4294936669
LOG: sending inval msg 29 0 26 1 30036 1310188568
LOG: sending inval msg 30 0 25 35 30036 4294936671
LOG: sending inval msg 29 0 25 35 30036 2633053415
LOG: sending inval msg 30 0 25 48 30036 4294936671
LOG: sending inval msg 29 0 25 48 30036 2633053415
LOG: sending inval msg 30 0 25 33 30036 4294936673
LOG: sending inval msg 29 0 25 33 30036 2049964857
LOG: sending inval msg 30 0 25 47 30036 4294936673
LOG: sending inval msg 29 0 25 47 30036 2049964857
LOG: sending inval msg -1 0 30036 0 30700 3218341912
LOG: sending inval msg -2 2084 1663 0 30036 50335
LOG: sending inval msg -2 0 1663 0 30036 50336
LOG: sending inval msg -1 2075 30036 0 30702 30036
LOG: sending inval msg -2 0 1663 0 30036 50324
LOG: sending inval msg -1 0 30036 0 30702 30036
LOG: sending inval msg -2 0 1663 0 30036 50336
LOG: sending inval msg -2 0 1663 0 30036 50323
LOG: sending inval msg -1 0 30036 0 30700 30036
LOG: sending inval msg -2 0 1663 0 30036 50335
LOG: sending inval msg -2 0 1663 0 30036 50322
LOG: sending inval msg -1 0 30036 0 30698 30036
LOG: sending inval msg -2 0 1663 0 30036 50334
LOG: sending inval msg -1 0 30036 0 30677 3218341912
LOG: sending inval msg -2 2084 1663 0 30036 50332
LOG: sending inval msg -2 0 1663 0 30036 50333
LOG: sending inval msg -1 2075 30036 0 30679 30036
LOG: sending inval msg -2 0 1663 0 30036 50321
LOG: sending inval msg -1 0 30036 0 30679 30036
LOG: sending inval msg -2 0 1663 0 30036 50333
LOG: sending inval msg -2 0 1663 0 30036 50320
LOG: sending inval msg -1 0 30036 0 30677 30036
LOG: sending inval msg -2 0 1663 0 30036 50332
LOG: sending inval msg -2 0 1663 0 30036 50319
LOG: sending inval msg -1 0 30036 0 30675 30036
LOG: sending inval msg -2 0 1663 0 30036 50331
LOG: sending inval msg -1 0 30036 0 30660 3218341912
LOG: sending inval msg -2 2084 1663 0 30036 50329
LOG: sending inval msg -2 0 1663 0 30036 50330
LOG: sending inval msg -1 2075 30036 0 30662 30036
LOG: sending inval msg -2 0 1663 0 30036 50318
LOG: sending inval msg -1 0 30036 0 30662 30036
LOG: sending inval msg -2 0 1663 0 30036 50330
LOG: sending inval msg -2 0 1663 0 30036 50317
LOG: sending inval msg -1 0 30036 0 30660 30036
LOG: sending inval msg -2 0 1663 0 30036 50329
LOG: sending inval msg -2 0 1663 0 30036 50316
LOG: sending inval msg -1 0 30036 0 30658 30036
LOG: sending inval msg -2 0 1663 0 30036 50328
LOG: sending inval msg -1 0 30036 0 30624 3218341912
LOG: sending inval msg -2 2084 1663 0 30036 50326
LOG: sending inval msg -2 0 1663 0 30036 50327
LOG: sending inval msg -1 2075 30036 0 30626 30036
LOG: sending inval msg -2 0 1663 0 30036 50315
LOG: sending inval msg -1 0 30036 0 30626 30036
LOG: sending inval msg -2 0 1663 0 30036 50327
LOG: sending inval msg -2 0 1663 0 30036 50314
LOG: sending inval msg -1 0 30036 0 30624 30036
LOG: sending inval msg -2 0 1663 0 30036 50326
LOG: sending inval msg -2 0 1663 0 30036 50313
LOG: sending inval msg -1 0 30036 0 30622 30036
LOG: sending inval msg -2 0 1663 0 30036 50325

Tom Lane napsal(a):
> Jakub Ouhrabka <kuba(at)comgate(dot)cz> writes:
>> We'we tried hard to identify what's the cause of filling sinval-queue.
>> We went through query logs as well as function bodies stored in the
>> database. We were not able to find any DDL, temp table creations etc.
>
> Strange. The best idea that comes to mind is to add some debugging
> code to SendSharedInvalidMessage to log the content of each message
> that's sent out. That would at least tell us *what* is going into
> the queue, even if not directly *why*. Try something like (untested)
>
> void
> SendSharedInvalidMessage(SharedInvalidationMessage *msg)
> {
> bool insertOK;
>
> + elog(LOG, "sending inval msg %d %u %u %u %u %u",
> + msg->cc.id,
> + msg->cc.tuplePtr.ip_blkid.bi_hi,
> + msg->cc.tuplePtr.ip_blkid.bi_lo,
> + msg->cc.tuplePtr.ip_posid,
> + msg->cc.dbId,
> + msg->cc.hashValue);
> +
> LWLockAcquire(SInvalLock, LW_EXCLUSIVE);
> insertOK = SIInsertDataEntry(shmInvalBuffer, msg);
> LWLockRelease(SInvalLock);
>
> regards, tom lane