Re: BUG #12718: Apparent LWlock Problem Perhaps With Page Cleanup

Yes.  It was pg_upgrad-ed from 9.2 almost a year ago (2014-02-27).
Unfortunately, I do not have the 9.2 data anymore.

It was pg_upgraded with the binaries in postgresql 9.3.1 which I
understand were affected by a bug related to leaving pg_multixact files
behind as per
http://www.postgresql.org/docs/9.4/static/release-9-3-5.html.  But the
query associated with the offsets/0000 bug, if I understand it, doesn't
seem to apply because offset 0000 doesn't exist in my case and therefore
the associated query returns False.

I'm afraid my grasp of MultiXacts isn't up to the task of understand
exactly what's going on.  By the time this issue is resolved I'm sure
I'll understand them better than I ever wanted to.  I'll attempt to
supply the same information as was requested in the referenced thread.



Here is the pg_controldata output:

pg_control version number:            937
Catalog version number:               201306121
Database system identifier:           5985061615841541596
Database cluster state:               in production
pg_control last modified:             Mon 02 Feb 2015 10:50:00 AM CST
Latest checkpoint location:           43A/607AD468
Prior checkpoint location:            43A/5DBA9040
Latest checkpoint's REDO location:    43A/5FF7A3C8
Latest checkpoint's REDO WAL file:    000000010000043A0000005F
Latest checkpoint's TimeLineID:       1
Latest checkpoint's PrevTimeLineID:   1
Latest checkpoint's full_page_writes: on
Latest checkpoint's NextXID:          0/487855284
Latest checkpoint's NextOID:          134556810
Latest checkpoint's NextMultiXactId:  1183038
Latest checkpoint's NextMultiOffset:  2584953
Latest checkpoint's oldestXID:        289465105
Latest checkpoint's oldestXID's DB:   16414
Latest checkpoint's oldestActiveXID:  487855284
Latest checkpoint's oldestMultiXid:   1
Latest checkpoint's oldestMulti's DB: 16414
Time of latest checkpoint:            Mon 02 Feb 2015 10:47:30 AM CST
Fake LSN counter for unlogged rels:   0/1
Minimum recovery ending location:     0/0
Min recovery ending loc's timeline:   0
Backup start location:                0/0
Backup end location:                  0/0
End-of-backup record required:        no
Current wal_level setting:            hot_standby
Current max_connections setting:      1000
Current max_prepared_xacts setting:   0
Current max_locks_per_xact setting:   128
Maximum data alignment:               8
Database block size:                  8192
Blocks per segment of large relation: 131072
WAL block size:                       8192
Bytes per WAL segment:                16777216
Maximum length of identifiers:        64
Maximum columns in an index:          32
Maximum size of a TOAST chunk:        1996
Date/time type storage:               64-bit integers
Float4 argument passing:              by value
Float8 argument passing:              by value
Data page checksum version:           0



leds=# SELECT datname, datfrozenxid, datminmxid FROM pg_database WHERE
datname = 'leds';
 datname | datfrozenxid | datminmxid
---------+--------------+------------
 leds    |    289465105 |          1
(1 row)



leds=# SELECT oid::regclass, relnamespace, relfrozenxid, relminmxid FROM
pg_class WHERE relname = 'addresses' AND relnamespace = 2200;
    oid    | relnamespace | relfrozenxid | relminmxid
-----------+--------------+--------------+------------
 addresses |         2200 |    354953499 |     261502



The oldest file in the cluster's pg_multixact/offsets directory is 0003
which as a modify time within an hour of pg_upgrade on 2014-02-27.



From where I was previously stuck, I shutdown the cluster "-m immediate"
and started it backup.  I disabled the script that was aggressively
updating the addresses table but have left autovacuum on.  My
understanding is that vacuuming the wrong pages will result in the same
sort of LWLock deadlock as occurred before.  Unfortunately this database
has fairly high uptime requirements, however I have a recent
pg_basebackup I can operate on which is exhibiting the same behavior.

Here is my current butchered 'understanding' of the problem:  There is
an incrementing value (MultiXactId) that tracks which process have which
locks on which tuples.  Since it's a finite (32bit in fact), it has to
wrap around eventually.  This requires something monitor where it is and
was and will be to handle wraparound cases and this job is given to
VACUUM.  Each table knows the oldest id that is has (relminmxid?) and as
VACUUM does its job, it updates keeps these up to date including
properly wrapping them around when necessary.  Somehow during pg_upgrade
the state of the multixactid state isn't fully transferred to the new
cluster (possibly due to known and documented bugs, and possibly because
of a yet unfound bug), and a cluster in that state is bound to run into
trouble when VACUUM discovers numbers that don't make sense.

I'll read up on what I can.  There seem to be plenty of relevant posts.
http://www.postgresql.org/message-id/5464A838.5070705@innogames.de

Let me know if I can supply any more information.  It sounds like there
are two fixes:
1.) Somehow set the values correctly which probably requries having a
copy of the pre-upgraded data around (I don't).
2.) Dump the database, reset the variables and reload the data.

Thanks
-Charles


I promised backtraces and here they are:
=============================================
This is the autovacuum process: (pid 24718)
=============================================

0x00007f5b1476e633 in select () from /lib/x86_64-linux-gnu/libc.so.6
#0  0x00007f5b1476e633 in select () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#1  0x00007f5b16a11dde in pg_usleep (microsec=<optimized out>) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/port/pgsleep.c:43
        delay = {tv_sec = 0, tv_usec = 449}
#2  0x00007f5b1674db6c in GetMultiXactIdMembers (allow_old=<optimized
out>, members=0x7ffff69aa3a0, multi=197438) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/access/transam/multixact.c:1261
        nextMXOffset = <optimized out>
        pageno = <optimized out>
        truelength = <optimized out>
        i = <optimized out>
        oldestMXact = <optimized out>
        nextMXact = <optimized out>
        ptr = <optimized out>
        entryno = <optimized out>
        length = <optimized out>
        tmpMXact = <optimized out>
        nextOffset = 4137329568
        prev_pageno = 96
        slotno = <optimized out>
        offptr = <optimized out>
        offset = 0
#3  GetMultiXactIdMembers (multi=197438, members=0x7ffff69aa3a0,
allow_old=<optimized out>) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/access/transam/multixact.c:1100
        length = 197439
#4  0x00007f5b1671fa08 in FreezeMultiXactId (flags=<synthetic pointer>,
cutoff_multi=<optimized out>, cutoff_xid=435461386,
t_infomask=<optimized out>, multi=197438) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/access/heap/heapam.c:5379
        members = <optimized out>
        nmembers = <optimized out>
        has_lockers = <optimized out>
        update_committed = <optimized out>
        xid = 0
        i = <optimized out>
        need_replace = <optimized out>
        nnewmembers = <optimized out>
        newmembers = <optimized out>
        update_xid = <optimized out>
#5  heap_prepare_freeze_tuple (tuple=0x7f59fd6f9240,
cutoff_xid=435461386, cutoff_multi=<optimized out>, frz=0x7f5b17620b6c)
at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/access/heap/heapam.c:5617
        flags = 0
        changed = 0 '\000'
        freeze_xmax = 0 '\000'
        xid = 197438
#6  0x00007f5b168221aa in lazy_scan_heap (scan_all=0 '\000', nindexes=8,
Irel=<optimized out>, vacrelstats=<optimized out>,
onerel=0x7f5b166002b0) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/commands/vacuumlazy.c:899
        buf = 347988
        page = 0x7f59fd6f8b80 "6\004"
        offnum = <optimized out>
        maxoff = 37
        hastup = 1 '\001'
        nfrozen = <optimized out>
        freespace = <optimized out>
        tupgone = 0 '\000'
        prev_dead_count = 0
        all_visible_according_to_vm = 0 '\000'
        all_visible = 0 '\000'
        has_dead_tuples = <optimized out>
        visibility_cutoff_xid = 0
        num_tuples = 2761072
        indstats = 0x7f5b17607aa0
        i = <optimized out>
        ru0 = {tv = {tv_sec = 1422574761, tv_usec = 520665}, ru =
{ru_utime = {tv_sec = 0, tv_usec = 524894}, ru_stime = {tv_sec = 0,
tv_usec = 302987}, ru_maxrss = 1077356, ru_ixrss = 0, ru_idrss = 0,
ru_isrss = 0, ru_minflt = 270000, ru_majflt = 0, ru_nswap = 0,
            ru_inblock = 0, ru_oublock = 112, ru_msgsnd = 0, ru_msgrcv =
0, ru_nsignals = 0, ru_nvcsw = 2090, ru_nivcsw = 6}}
        frozen = 0x7f5b17620b60
        blkno = <optimized out>
        empty_pages = <optimized out>
        vacuumed_pages = <optimized out>
        tups_vacuumed = 0
        nkeep = 593975
        next_not_all_visible_block = <optimized out>
        skipping_all_visible_blocks = 0 '\000'
        nblocks = 98427
        relname = 0x7f5b16601d30 "addresses"
        nunused = 0
        vmbuffer = 183145
#7  lazy_vacuum_rel (onerel=0x7f5b166002b0, vacstmt=<optimized out>,
bstrategy=<optimized out>) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/commands/vacuumlazy.c:236
        vacrelstats = <optimized out>
        Irel = 0x7f5b17624ac8
        nindexes = 8
        possibly_freeable = <optimized out>
        ru0 = {tv = {tv_sec = 140029210944257, tv_usec =
140029198239941}, ru = {ru_utime = {tv_sec = 140029211069184, tv_usec =
140029211068928}, ru_stime = {tv_sec = 844429225099264, tv_usec =
429496729600}, ru_maxrss = 140029197707696, ru_ixrss = 281483566645432,
            ru_idrss = 140029194147330, ru_isrss = 0, ru_minflt =
140737330718495, ru_majflt = 140029194142448, ru_nswap =
140029162548016, ru_inblock = 4, ru_oublock = 140737330718192, ru_msgsnd
= 140029194142384, ru_msgrcv = 7, ru_nsignals = 0,
            ru_nvcsw = 140029194147408, ru_nivcsw = 8}}
        starttime = 0
        secs = <optimized out>
        usecs = <optimized out>
        read_rate = <optimized out>
        write_rate = <optimized out>
        scan_all = 0 '\000'
        scanned_all = <optimized out>
        xidFullScanLimit = 335823296
        mxactFullScanLimit = 4146143161
        new_rel_pages = <optimized out>
        new_rel_tuples = <optimized out>
        new_rel_allvisible = <optimized out>
        new_frozen_xid = <optimized out>
        new_min_multi = <optimized out>
        __func__ = "lazy_vacuum_rel"
#8  0x00007f5b1681fc75 in vacuum_rel (relid=17441,
vacstmt=0x7ffff69aabb0, do_toast=0 '\000', for_wraparound=0 '\000') at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/commands/vacuum.c:1288
        lmode = 4
        onerel = 0x7f5b166002b0
        onerelid = {relId = 17441, dbId = 16414}
        toast_relid = 0
        save_userid = <optimized out>
        save_sec_context = 0
        save_nestlevel = <optimized out>
        __func__ = "vacuum_rel"
#9  0x00007f5b16820b05 in vacuum (vacstmt=0x7ffff69aabb0,
relid=<optimized out>, do_toast=0 '\000', bstrategy=<optimized out>,
for_wraparound=0 '\000', isTopLevel=<optimized out>) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/commands/vacuum.c:237
        relid = 17441
        cur = 0x7f5b177d0460
        save_exception_stack = 0x7ffff69aa9e0
        save_context_stack = 0x0
        local_sigjmp_buf = {{__jmpbuf = {140029202659720,
1004169673111825598, 17441, 140029210764256, 20, 200,
1004169673157962942, 911493825480551614}, __mask_was_saved = 0,
__saved_mask = {__val = {0, 140737330718960, 140737331063969, 0,
140029211147472, 8432298256,
                140029055545016, 140737330719728, 2, 140737330718992,
140029197856355, 1422574761, 520095, 140737330719056, 140029197018826,
140737330719040}}}}
        stmttype = <optimized out>
        in_outer_xact = 0 '\000'
        use_own_xacts = 1 '\001'
        relations = 0x7f5b177d0480
#10 0x00007f5b168b6bfa in autovacuum_do_vac_analyze
(bstrategy=0x7f5b17637a60, tab=0x7f5b17637c80) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/postmaster/autovacuum.c:2811
        vacstmt = {type = T_VacuumStmt, options = 33, freeze_min_age =
50000000, freeze_table_age = 150000000, relation = 0x7ffff69aab70,
va_cols = 0x0, multixact_freeze_min_age = 5000000,
multixact_freeze_table_age = 150000000}
        rangevar = {type = T_Invalid, catalogname = 0x0, schemaname =
0x7f5b17637cd0 "public", relname = 0x7f5b17637a40 "addresses", inhOpt =
INH_NO, relpersistence = 0 '\000', alias = 0x0, location = -1}
#11 do_autovacuum () at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/postmaster/autovacuum.c:2329
        save_exception_stack = 0x7ffff69aacf0
        save_context_stack = 0x0
        local_sigjmp_buf = {{__jmpbuf = {17441, 1004169673302666430,
5000000, 140029211147120, 20, 200, 1004169673118117054,
911493888709422270}, __mask_was_saved = 0, __saved_mask = {__val =
{140029202655000, 140029202657676, 140029202659752, 140029193999920, 1,
                140737330719600, 140029198332043, 0, 8606777346,
140029209619712, 0, 140737330719984, 140029209619712, 140029202345472,
1004169673048911038, 140029202657676}}}}
        tab = 0x7f5b17637c80
        skipit = 0 '\000'
        stdVacuumCostDelay = 0
        stdVacuumCostLimit = 200
        iter = <optimized out>
        relid = 17441
        classRel = 0x7f5b165d2430
        tuple = <optimized out>
        relScan = <optimized out>
        dbForm = <optimized out>
        table_oids = <optimized out>
        ctl = {num_partitions = 0, ssize = 0, dsize = 0, max_dsize = 0,
ffactor = 0, keysize = 4, entrysize = 64, hash = 0x7f5b169e9950
<oid_hash>, match = 0, keycopy = 0, alloc = 0, hcxt = 0x0, hctl = 0x0}
        table_toast_map = 0x7f5b17638390
        cell = 0x7f5b17637a20
        shared = 0x7f5b176089f8
        dbentry = 0x7f5b17608c80
        bstrategy = 0x7f5b17637a60
        key = {sk_flags = 0, sk_attno = 17, sk_strategy = 3, sk_subtype
= 0, sk_collation = 100, sk_func = {fn_addr = 0x7f5b16931a50 <chareq>,
fn_oid = 61, fn_nargs = 2, fn_strict = 1 '\001', fn_retset = 0 '\000',
fn_stats = 2 '\002', fn_extra = 0x0,
            fn_mcxt = 0x7f5b174c2bf0, fn_expr = 0x0}, sk_argument = 116}
        pg_class_desc = 0x7f5b17636380
        __func__ = "do_autovacuum"
#12 0x00007f5b168b70f6 in AutoVacWorkerMain (argc=<optimized out>,
argv=<optimized out>) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/postmaster/autovacuum.c:1679
        dbname =

"leds\000\000\000\000I\245\230\025[\177\000\000\000\000\000\000\000\000\000\000È\213\026[\177\000\000\060\n\000\366\377\177\000\000
\227\243\024[\177\000\000
\256\232\366\377\177\000\000\034\020\214\026[\177\000"
        local_sigjmp_buf = {{__jmpbuf = {0, 1004169673227168958, 4,
140029209964800, 140029202359232, 24717, 1004169673300569278,
911493888971435198}, __mask_was_saved = 1, __saved_mask = {__val =
{18446744066192964103, 12, 0, 0, 140737330720112, 140737330720208,
                140029161902022, 140029165031304, 140737330720144,
140029162696144, 140029199346469, 140029165026144, 0, 140029194442432,
140029161901637, 140029194442432}}}}
        dbid = 16414
#13 0x00007f5b168b71ba in StartAutoVacWorker () at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/postmaster/autovacuum.c:1464
        worker_pid = 0
        __func__ = "StartAutoVacWorker"
#14 0x00007f5b168c46d5 in StartAutovacuumWorker () at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/postmaster/postmaster.c:5070
        bn = 0x7f5b17517100
#15 sigusr1_handler (postgres_signal_arg=<optimized out>) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/postmaster/postmaster.c:4725
        save_errno = 4
        __func__ = "sigusr1_handler"
#16 <signal handler called>
No symbol table info available.
#17 0x00007f5b1476e633 in select () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#18 0x00007f5b168c3943 in ServerLoop () at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/postmaster/postmaster.c:1546
        timeout = {tv_sec = 59, tv_usec = 882764}
        rmask = {fds_bits = {776, 0 <repeats 15 times>}}
        selres = <optimized out>
        readmask = {fds_bits = {776, 0 <repeats 15 times>}}
        nSockets = 10
        now = <optimized out>
        last_touch_time = 1422573909
#19 PostmasterMain (argc=<optimized out>, argv=<optimized out>) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/postmaster/postmaster.c:1253
        opt = <optimized out>
        status = <optimized out>
        userDoption = <optimized out>
        listen_addr_saved = <optimized out>
        i = <optimized out>
        __func__ = "PostmasterMain"
#20 0x00007f5b166f8687 in main (argc=5, argv=0x7f5b174c11a0) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/main/main.c:226






======================================
Here is the process (2900) that was doing the heavy writing/many
transactions:
======================================
#0  0x00007f5b147773e7 in semop () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#1  0x00007f5b168b40c2 in PGSemaphoreLock (sema=0x7f5b0e171550,
interruptOK=0 '\000') at pg_sema.c:421
        errStatus = <optimized out>
        sops = {sem_num = 5, sem_op = -1, sem_flg = 0}
        __func__ = "PGSemaphoreLock"
#2  0x00007f5b168fb46b in LWLockAcquire (lockid=696144, mode=LW_SHARED)
at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/storage/lmgr/lwlock.c:480
        mustwait = 1 '\001'
        lock = 0x7f594d96da80
        proc = 0x7f5b0e171540
        retry = 0 '\000'
        extraWaits = 0
        __func__ = "LWLockAcquire"
#3  0x00007f5b1672b1c3 in index_fetch_heap (scan=0x7f5b17693f50) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/access/index/indexam.c:528
        tid = 0x7f5b17693fa4
        all_dead = 0 '\000'
        got_heap_tuple = <optimized out>
#4  0x00007f5b1672b2ce in index_getnext (scan=0x7f5b17693f50,
direction=ForwardScanDirection) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/access/index/indexam.c:612
        heapTuple = <optimized out>
        tid = <optimized out>
#5  0x00007f5b1683b0e5 in IndexNext (node=0x7f5b176920c0) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/executor/nodeIndexscan.c:78
        estate = <optimized out>
        econtext = 0x7f5b176921d0
        direction = ForwardScanDirection
        scandesc = 0x7f5b17693f50
        tuple = <optimized out>
        slot = 0x7f5b17693430
#6  0x00007f5b16830806 in ExecScanFetch (recheckMtd=0x7f5b1683b050
<IndexRecheck>, accessMtd=0x7f5b1683b090 <IndexNext>,
node=0x7f5b176920c0) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/executor/execScan.c:82
        estate = <optimized out>
#7  ExecScan (node=0x7f5b176920c0, accessMtd=0x7f5b1683b090 <IndexNext>,
recheckMtd=0x7f5b1683b050 <IndexRecheck>) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/executor/execScan.c:167
        slot = 0x7f5b176920c0
        econtext = 0x7f5b176921d0
        qual = 0x0
        projInfo = 0x7f5b17693880
        isDone = 32603
        resultSlot = <optimized out>
#8  0x00007f5b168295a8 in ExecProcNode (node=0x7f5b176920c0) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/executor/execProcnode.c:404
        result = <optimized out>
        __func__ = "ExecProcNode"
#9  0x00007f5b1683fa0d in ExecModifyTable (node=0x7f5b176c8058) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/executor/nodeModifyTable.c:918
        estate = 0x7f5b176d4140
        operation = CMD_UPDATE
        saved_resultRelInfo = 0x0
        resultRelInfo = 0x7f5b176d42d0
        subplanstate = 0x7f5b176920c0
        junkfilter = 0x7f5b17695418
        slot = <optimized out>
        planSlot = <optimized out>
        tupleid = 0x0
        tuple_ctid = {ip_blkid = {bi_hi = 16704, bi_lo = 5997}, ip_posid
= 32603}
        oldtuple = 0x0
        __func__ = "ExecModifyTable"
#10 0x00007f5b168295f8 in ExecProcNode (node=0x7f5b176c8058) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/executor/execProcnode.c:377
        result = <optimized out>
        __func__ = "ExecProcNode"
#11 0x00007f5b16826907 in ExecutePlan (dest=0x7f5b1768a998,
direction=<optimized out>, numberTuples=0, sendTuples=0 '\000',
operation=CMD_UPDATE, planstate=0x7f5b176c8058, estate=0x7f5b176d4140)
    at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/executor/execMain.c:1473
        slot = <optimized out>
        current_tuple_count = 0
#12 standard_ExecutorRun (queryDesc=0x7f5b176b18b0, direction=<optimized
out>, count=0) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/executor/execMain.c:307
        estate = 0x7f5b176d4140
        operation = CMD_UPDATE
        dest = 0x7f5b1768a998
        sendTuples = <optimized out>
        oldcontext = 0x7f5b176403f0
#13 0x00007f5b1690ba44 in ProcessQuery (plan=0x7f5b1768a8b8,
    sourceText=0x7f5b174db4c0 "\n\t\t\t\t  UPDATE addresses\n\t\t\t\t
SET num_type = NULL,\n\t\t\t\t\t  num_1 = E'5262',\n\t\t\t\t\t  num_2 =
NULL,\n\t\t\t\t\t  street = E'5262 240TH ST',\n\t\t\t\t\t  street_1 =
E'240TH ST',\n\t\t\t\t\t  street_2 = NULL,\n\t\t\t\t\t  unit_typ"...,
params=<optimized out>, dest=0x7f5b1768a998,
completionTag=0x7ffff69ab230 "") at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/tcop/pquery.c:185
        queryDesc = 0x7f5b176b18b0
        __func__ = "ProcessQuery"
#14 0x00007f5b1690bc7b in PortalRunMulti (portal=0x7f5b17608030,
isTopLevel=1 '\001', dest=0x7f5b1768a998, altdest=0x7f5b1768a998,
completionTag=0x7ffff69ab230 "") at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/tcop/pquery.c:1279
        pstmt = 0x7f5b1768a8b8
        stmt = 0x7f5b1768a8b8
        active_snapshot_set = 1 '\001'
        stmtlist_item = 0x7f5b1768a948
#15 0x00007f5b1690c94d in PortalRun (portal=0x7f5b17608030,
count=9223372036854775807, isTopLevel=1 '\001', dest=0x7f5b1768a998,
altdest=0x7f5b1768a998, completionTag=0x7ffff69ab230 "") at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/tcop/pquery.c:816
        save_exception_stack = 0x7ffff69ab110
        save_context_stack = 0x0
        local_sigjmp_buf = {{__jmpbuf = {140029209727360,
1004169673422204094, 140029210951728, 140029209727440, 140029211486616,
2, 1004169673241849022, 911493952020212926}, __mask_was_saved = 0,
__saved_mask = {__val = {1, 140737330720751, 140029199549563,
                140029198238304, 64, 140737330720720, 88,
140029210951728, 140029209727440, 140029199440175, 2, 140737330720752,
140029198326346, 2, 140029210951728, 140737330720784}}}}
        result = <optimized out>
        nprocessed = <optimized out>
        saveTopTransactionResourceOwner = 0x7f5b174c2d50
        saveTopTransactionContext = 0x7f5b174c14e0
        saveActivePortal = 0x0
        saveResourceOwner = 0x7f5b174c2d50
        savePortalContext = 0x0
        saveMemoryContext = 0x7f5b174c14e0
        __func__ = "PortalRun"
#16 0x00007f5b16908b5c in exec_simple_query (
    query_string=0x7f5b174db4c0 "\n\t\t\t\t  UPDATE addresses\n\t\t\t\t
SET num_type = NULL,\n\t\t\t\t\t  num_1 = E'5262',\n\t\t\t\t\t  num_2 =
NULL,\n\t\t\t\t\t  street = E'5262 240TH ST',\n\t\t\t\t\t  street_1 =
E'240TH ST',\n\t\t\t\t\t  street_2 = NULL,\n\t\t\t\t\t  unit_typ"...) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/tcop/postgres.c:1048
        parsetree = 0x7f5b174dd180
        portal = 0x7f5b17608030
        snapshot_set = <optimized out>
        commandTag = <optimized out>
        completionTag = "\000PDATE

1\000\060\065\070\071\060\000\000`\273\243\024[\177\000\000\000\000\000\000\000\000\000\000\b\000\000\000\000\000\000\000E\016t\024[\177\000\000\b\000\000\000\000\000\000\000\212\226\230\025[\177\000"
        querytree_list = <optimized out>
        plantree_list = 0x7f5b1768a968
        receiver = 0x7f5b1768a998
        format = 0
        dest = DestRemote
        parsetree_list = 0x7f5b174dd1f0
        save_log_statement_stats = 0 '\000'
        was_logged = 0 '\000'
        msec_str = "224.871\000\000\000\230\025[\177", '\000' <repeats
14 times>, "[\177\000"
        parsetree_item = 0x7f5b174dd1d0
        isTopLevel = 1 '\001'
#17 PostgresMain (argc=<optimized out>, argv=<optimized out>,
dbname=0x7f5b174c2058 "leds", username=<optimized out>) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/tcop/postgres.c:4007
        query_string = 0x7f5b174db4c0 "\n\t\t\t\t  UPDATE
addresses\n\t\t\t\t  SET num_type = NULL,\n\t\t\t\t\t  num_1 =
E'5262',\n\t\t\t\t\t  num_2 = NULL,\n\t\t\t\t\t  street = E'5262 240TH
ST',\n\t\t\t\t\t  street_1 = E'240TH ST',\n\t\t\t\t\t  street_2 =
NULL,\n\t\t\t\t\t  unit_typ"...
        firstchar = 390975872
        input_message = {
          data = 0x7f5b174db4c0 "\n\t\t\t\t  UPDATE addresses\n\t\t\t\t
SET num_type = NULL,\n\t\t\t\t\t  num_1 = E'5262',\n\t\t\t\t\t  num_2 =
NULL,\n\t\t\t\t\t  street = E'5262 240TH ST',\n\t\t\t\t\t  street_1 =
E'240TH ST',\n\t\t\t\t\t  street_2 = NULL,\n\t\t\t\t\t  unit_typ"...,
len = 457, maxlen = 1024, cursor = 457}
        local_sigjmp_buf = {{__jmpbuf = {140029202659696,
1004169673363483838, 140029209616448, 1, 140029202359232, 0,
1004169673428495550, 911493949973916862}, __mask_was_saved = 1,
__saved_mask = {__val = {0, 0, 65280, 0, 0, 140737330721488, 14,
140737330721424,
                140029202359232, 2895, 140029162201848, 0, 206158430256,
140737330721424, 140737330721232, 0}}}}
        send_ready_for_query = 0 '\000'
        __func__ = "PostgresMain"
#18 0x00007f5b168c422d in BackendRun (port=0x7f5b1750b080) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/postmaster/postmaster.c:4011
        ac = 1
        secs = 475880591
        usecs = 771115
        i = 1
        av = 0x7f5b174c2070
        maxac = <optimized out>
#19 BackendStartup (port=0x7f5b1750b080) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/postmaster/postmaster.c:3685
        bn = <optimized out>
        pid = 0
#20 ServerLoop () at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/postmaster/postmaster.c:1586
        port = 0x7f5b1750b080
        rmask = {fds_bits = {512, 0 <repeats 15 times>}}
        selres = <optimized out>
        readmask = {fds_bits = {776, 0 <repeats 15 times>}}
        nSockets = 10
        now = <optimized out>
        last_touch_time = 1422563469
#21 PostmasterMain (argc=<optimized out>, argv=<optimized out>) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/postmaster/postmaster.c:1253
        opt = <optimized out>
        status = <optimized out>
        userDoption = <optimized out>
        listen_addr_saved = <optimized out>
        i = <optimized out>
        __func__ = "PostmasterMain"
#22 0x00007f5b166f8687 in main (argc=5, argv=0x7f5b174c11a0) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/main/main.c:226






======================================
And here is one of the many processes that were attempting SELECTs from
that table.  Pid
======================================
#0  0x00007f5b147773e7 in semop () from /lib/x86_64-linux-gnu/libc.so.6
No symbol table info available.
#1  0x00007f5b168b40c2 in PGSemaphoreLock (sema=0x7f5b0e109790,
interruptOK=0 '\000') at pg_sema.c:421
        errStatus = <optimized out>
        sops = {sem_num = 3, sem_op = -1, sem_flg = 0}
        __func__ = "PGSemaphoreLock"
#2  0x00007f5b168fb46b in LWLockAcquire (lockid=696144, mode=LW_SHARED)
at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/storage/lmgr/lwlock.c:480
        mustwait = 1 '\001'
        lock = 0x7f594d96da80
        proc = 0x7f5b0e109780
        retry = 0 '\000'
        extraWaits = 0
        __func__ = "LWLockAcquire"
#3  0x00007f5b1671d03a in heapgetpage (page=71845, scan=0x7f5b1863e840)
at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/access/heap/heapam.c:350
        buffer = 347988
        snapshot = 0x7f5b17a6de80
        dp = <optimized out>
        lines = <optimized out>
        lineoff = <optimized out>
        ntup = <optimized out>
        lpp = <optimized out>
        all_visible = <optimized out>
#4  heapgetpage (scan=0x7f5b1863e840, page=71845) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/access/heap/heapam.c:301
No locals.
#5  0x00007f5b1671d500 in heapgettup_pagemode (scan=0x7f5b1863e840,
dir=<optimized out>, nkeys=0, key=0x0) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/access/heap/heapam.c:936
        tuple = 0x7f5b1863e880
        backward = 0 '\000'
        page = 71845
        finished = 0 '\000'
        dp = 0x7f5a72b3eb80 "8\004"
        lines = <optimized out>
        lineindex = 6
        lineoff = <optimized out>
        linesleft = 0
        lpp = <optimized out>
#6  0x00007f5b1671e89e in heap_getnext (scan=0x7f5b1863e840,
direction=<optimized out>) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/access/heap/heapam.c:1456
No locals.
#7  0x00007f5b1684201d in SeqNext (node=<optimized out>) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/executor/nodeSeqscan.c:66
        tuple = <optimized out>
        scandesc = 0x7f5b1863e840
        estate = <optimized out>
        direction = <optimized out>
        slot = 0x7f5b1863e790
#8  0x00007f5b16830806 in ExecScanFetch (recheckMtd=0x7f5b16841fe0
<SeqRecheck>, accessMtd=0x7f5b16841ff0 <SeqNext>, node=0x7f5b1794ebb0)
at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/executor/execScan.c:82
        estate = <optimized out>
#9  ExecScan (node=0x7f5b1794ebb0, accessMtd=0x7f5b16841ff0 <SeqNext>,
recheckMtd=0x7f5b16841fe0 <SeqRecheck>) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/executor/execScan.c:167
        slot = 0x7f5b1863e790
        econtext = 0x7f5b1794ecc0
        qual = 0x7f5b1857dc30
        projInfo = 0x7f5b1863f540
        isDone = 32603
        resultSlot = <optimized out>
#10 0x00007f5b168295b8 in ExecProcNode (node=0x7f5b1794ebb0) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/executor/execProcnode.c:400
        result = <optimized out>
        __func__ = "ExecProcNode"
#11 0x00007f5b16842ae1 in ExecSort (node=0x7f5b1794e910) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/executor/nodeSort.c:103
        plannode = <optimized out>
        outerNode = 0x7f5b1794ebb0
        tupDesc = <optimized out>
        estate = 0x7f5b1794e7b0
        dir = ForwardScanDirection
        tuplesortstate = 0x7f5b18644230
        slot = <optimized out>
#12 0x00007f5b168294c8 in ExecProcNode (node=0x7f5b1794e910) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/executor/execProcnode.c:468
        result = <optimized out>
        __func__ = "ExecProcNode"
#13 0x00007f5b16826907 in ExecutePlan (dest=0x7f5b18520038,
direction=<optimized out>, numberTuples=0, sendTuples=1 '\001',
operation=CMD_SELECT, planstate=0x7f5b1794e910, estate=0x7f5b1794e7b0)
    at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/executor/execMain.c:1473
        slot = <optimized out>
        current_tuple_count = 0
#14 standard_ExecutorRun (queryDesc=0x7f5b1842cbb0, direction=<optimized
out>, count=0) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/executor/execMain.c:307
        estate = 0x7f5b1794e7b0
        operation = CMD_SELECT
        dest = 0x7f5b18520038
        sendTuples = <optimized out>
        oldcontext = 0x7f5b183abd80
#15 0x00007f5b1690b427 in PortalRunSelect (portal=0x7f5b17613950,
forward=<optimized out>, count=0, dest=<optimized out>) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/tcop/pquery.c:946
        queryDesc = 0x7f5b1842cbb0
        direction = ForwardScanDirection
        nprocessed = <optimized out>
        __func__ = "PortalRunSelect"
#16 0x00007f5b1690c8af in PortalRun (portal=0x7f5b17613950,
count=9223372036854775807, isTopLevel=1 '\001', dest=0x7f5b18520038,
altdest=0x7f5b18520038, completionTag=0x7ffff69ab230 "") at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/tcop/pquery.c:790
        save_exception_stack = 0x7ffff69ab110
        save_context_stack = 0x0
        local_sigjmp_buf = {{__jmpbuf = {140029225580208,
1004169673422204094, 140029210999120, 140029225582896, 140029226778680,
2, 1004169673241849022, 911493952020212926}, __mask_was_saved = 0,
__saved_mask = {__val = {1, 140737330720751, 140029199549563,
                140029198238304, 64, 140737330720720, 88,
140029210999120, 140029225582896, 140029199307619, 2, 140737330720752,
140029198326346, 2, 140029210999120, 140737330720784}}}}
        result = <optimized out>
        nprocessed = <optimized out>
        saveTopTransactionResourceOwner = 0x7f5b174c2d50
        saveTopTransactionContext = 0x7f5b185c9a90
        saveActivePortal = 0x0
        saveResourceOwner = 0x7f5b174c2d50
        savePortalContext = 0x0
        saveMemoryContext = 0x7f5b185c9a90
        __func__ = "PortalRun"
#17 0x00007f5b16908b5c in exec_simple_query (
    query_string=0x7f5b174dbce0 "SELECT '', '', street, city, state,
zipcode, address_groupsid,  addressesid FROM ((SELECT
a.address_groupsid,\n\t\t          a.addressesid,\n\t\t
a.num_type,\n\t\t          a.num_1,\n\t\t          a.num_"...)
    at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/tcop/postgres.c:1048
        parsetree = 0x7f5b183fb6b0
        portal = 0x7f5b17613950
        snapshot_set = <optimized out>
        commandTag = <optimized out>
        completionTag = "\000ELECT
1\000E\000X\000\000\000\000`\273\243\024[\177", '\000' <repeats 18
times>,
"E\016t\024[\177\000\000\000\000\000\000\000\000\000\000\212\226\230\025[\177\000"
        querytree_list = <optimized out>
        plantree_list = 0x7f5b18520008
        receiver = 0x7f5b18520038
        format = 0
        dest = DestRemote
        parsetree_list = 0x7f5b183fc150
        save_log_statement_stats = 0 '\000'
        was_logged = 0 '\000'
        msec_str =
"453.861\000\000\245\230\025[\177\000\000\000\000\000\000\000\000\000\000\064\071\062\071\063\000\000"
        parsetree_item = 0x7f5b183fc130
        isTopLevel = 1 '\001'
#18 PostgresMain (argc=<optimized out>, argv=<optimized out>,
dbname=0x7f5b174c2058 "leds", username=<optimized out>) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/tcop/postgres.c:4007
        query_string = 0x7f5b174dbce0 "SELECT '', '', street, city,
state, zipcode, address_groupsid,  addressesid FROM ((SELECT
a.address_groupsid,\n\t\t          a.addressesid,\n\t\t
a.num_type,\n\t\t          a.num_1,\n\t\t          a.num_"...
        firstchar = 406828720
        input_message = {data = 0x7f5b174dbce0 "SELECT '', '', street,
city, state, zipcode, address_groupsid,  addressesid FROM ((SELECT
a.address_groupsid,\n\t\t          a.addressesid,\n\t\t
a.num_type,\n\t\t          a.num_1,\n\t\t          a.num_"...,
          len = 1146, maxlen = 2048, cursor = 1146}
        local_sigjmp_buf = {{__jmpbuf = {140029202659696,
1004169673363483838, 140029209616448, 1, 140029202359232, 0,
1004169673428495550, 911493949973916862}, __mask_was_saved = 1,
__saved_mask = {__val = {0, 0, 65280, 0, 0, 140737330721488, 14,
140737330721424,
                140029202359232, 2365, 140029162201848, 0, 206158430256,
140737330721424, 140737330721232, 0}}}}
        send_ready_for_query = 0 '\000'
        __func__ = "PostgresMain"
#19 0x00007f5b168c422d in BackendRun (port=0x7f5b1750b080) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/postmaster/postmaster.c:4011
        ac = 1
        secs = 475880538
        usecs = 428207
        i = 1
        av = 0x7f5b174c2070
        maxac = <optimized out>
#20 BackendStartup (port=0x7f5b1750b080) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/postmaster/postmaster.c:3685
        bn = <optimized out>
        pid = 0
#21 ServerLoop () at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/postmaster/postmaster.c:1586
        port = 0x7f5b1750b080
        rmask = {fds_bits = {8, 0 <repeats 15 times>}}
        selres = <optimized out>
        readmask = {fds_bits = {776, 0 <repeats 15 times>}}
        nSockets = 10
        now = <optimized out>
        last_touch_time = 1422563469
#22 PostmasterMain (argc=<optimized out>, argv=<optimized out>) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/postmaster/postmaster.c:1253
        opt = <optimized out>
        status = <optimized out>
        userDoption = <optimized out>
        listen_addr_saved = <optimized out>
        i = <optimized out>
        __func__ = "PostmasterMain"
#23 0x00007f5b166f8687 in main (argc=5, argv=0x7f5b174c11a0) at
/tmp/buildd/postgresql-9.3-9.3.5/build/../src/backend/main/main.c:226




On 01/30/2015 06:41 PM, Peter Geoghegan wrote:
> On Fri, Jan 30, 2015 at 2:14 PM,  <charles.harwood@zuerchertech.com> wrote:
>> Many postgres worker processes stopped responding.  They continued to be in
>> state 'active' and not 'waiting' for hours.  Each query was on the table
>> that an autovacuum process was also hung on processing and was the oldest
>> active transaction on.
>
> Was pg_upgrade run on this database at some point [1]?
>
> I foresee more problems here...
>
> [1] http://www.postgresql.org/message-id/20140825225029.2536.5315@wrigleys.postgresql.org