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@comgate.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