Upgrading with extensions getting a row is too big

[robe]

This is really odd. I was doing great with the:

ALTER EXTENSION postgis UPDATE TO "2.1.0SVNnext";
ALTER EXTENSION postgis UPDATE TO "2.1.0SVN";

Until now. Don't know if its a change in our code or my packaging or a bug in extension system.

This is going from: 2.1.0SVN r10181 to 2.1.0SVN r10191

I get this error:

 row is too big: size 9280, maximum size 8160

I thought it might be a bug in PostgreSQL 9.2beta3, but i get the same weirdness on my 9.1 64-bit install. Except on my 64-bit I was able to do the first part but not the second. My 9.2 is a much more complicated database I restored from 8.4 that I was successful upgrading 3 times. This is using the latest 64-bit windows buildbot builds.

[robe]

I was able to recreate with a fresh new database on my 9.1 install by doing each of these steps separately:

CREATE EXTENSION postgis;
ALTER EXTENSION postgis UPDATE TO "2.1.0SVNnext";
ALTER EXTENSION postgis UPDATE TO "2.1.0SVN";
-- this last one fails with a row is too big: size 9280, maximum size 8160
ALTER EXTENSION postgis UPDATE TO "2.1.0SVNnext";

What's really odd is I thought I had been doing this for a while with no issue. I'm going to next try installing the old fashioned way to verify this is an extension issue and not our general upgrade script.

[robe]

okay only seems to be an issue with extension script and logs aren't very helpful.

Would be good if non-windows folks can try the same to see if its just a windows issue. Last time I saw this kind of issue was a collation bug.

[robe]

tried on my 9.2 x32bit and same issue. For postgis_topology that seems fine. I changed about 10 times with no issue. So must be a combination of factors.

[robe]

seems to be something in the raster logic tripping it up. If I cut out the raster upgrade logic from the extension it works fine.

[robe]

I reported this issue upstream ​http://archives.postgresql.org/pgsql-bugs/2012-12/msg00154.php

Andres Freund ​http://archives.postgresql.org/pgsql-bugs/2012-12/msg00155.php suggested I turn on verbosity. Duh why didn't I think of that. running this

SET log_error_verbosity = 'verbose';
ALTER EXTENSION postgis UPDATE TO "2.1.0SVN";

shows this in the log file

2012-12-17 09:15:10 EST LOG:  statement: 
	SET log_error_verbosity = 'verbose';
2012-12-17 09:15:13 EST LOG:  00000: statement: ALTER EXTENSION postgis
	  UPDATE TO "2.1.0SVN";
2012-12-17 09:15:13 EST LOCATION:  exec_simple_query, src\backend\tcop\postgres.c:888
2012-12-17 09:15:15 EST ERROR:  54000: row is too big: size 9272, maximum size 8160
2012-12-17 09:15:15 EST LOCATION:  RelationGetBufferForTuple, src\backend\access\heap\hio.c:241

[robe]

As suggested by Andres. I did a back trace against my mingw64 windows 32-bit (this one is running 9.2.1 haven't upgraded it to 9.2.2 yet) install exhibits same issue as my EDB install. EDB bt provided no useful info: but mingw bt provided this. Which I'm not sure is useful or not.

# SELECT pg_backend_pid();
> 5416

$ gdb -p 5416
(gdb) b hio.c:24
(gdb) c
....

# ALTER EXTENSION postgis UPDATE TO "2.1.0SVN";
(gdb) bt full

Yields:

Breakpoint 1 at 0x429df0: file hio.c, line 24.
(gdb) c
Continuing.
[Switching to Thread 5416.0x174]

Breakpoint 1, RelationPutHeapTuple (relation=0x1d749d8, buffer=1640,
    tuple=0x1da9500) at hio.c:38
38      {
(gdb) bt full
#0  RelationPutHeapTuple (relation=0x1d749d8, buffer=1640, tuple=0x1da9500)
    at hio.c:38
        pageHeader = <optimized out>
        offnum = <optimized out>
        __func__ = "RelationPutHeapTuple"
#1  0x004250de in heap_update (relation=0x1d749d8, otid=0x1da9504,
    newtup=0x1da9500, ctid=0x1ccef36, update_xmax=0x1ccef3c, cid=0,
    crosscheck=0x0, wait=1 '\001') at heapam.c:3156
        result = <optimized out>
        xid = 697
        hot_attrs = 0x1d9a398
        lp = <optimized out>
        oldtup = {t_len = 7011, t_self = {ip_blkid = {bi_hi = 0, bi_lo = 3},
            ip_posid = 1}, t_tableOid = 8, t_data = 0x4962258}
        heaptup = 0x1da9500
        page = <optimized out>
        block = 1640
        buffer = <optimized out>
        newbuf = 1640
        vmbuffer = 0
        vmbuffer_new = 0
        need_toast = 0 '\000'
        already_marked = <optimized out>
        newtupsize = <optimized out>
        pagefree = <optimized out>
        have_tuple_lock = <optimized out>
        iscombo = 0 '\000'
        use_hot_update = 0 '\000'
        all_visible_cleared = 0 '\000'
        all_visible_cleared_new = 0 '\000'
        __func__ = "heap_update"
#2  0x004265ad in simple_heap_update (relation=0x1d749d8, otid=0x1da9504,
    tup=0x1da9500) at heapam.c:3384
        result = <optimized out>
        update_ctid = {ip_blkid = {bi_hi = 0, bi_lo = 39130},
          ip_posid = 30410}
        update_xmax = 31036508
        __func__ = "simple_heap_update"
#3  0x0051390d in ApplyExtensionUpdates (extensionOid=24579,
    pcontrol=0x1d67530, initialVersion=0x39a0290 "2.1.0SVN",
    updateVersions=0x1d99920) at extension.c:2579
        control = 0x1d67580
        schemaName = 0x1d9a310 "public"
        schemaOid = <optimized out>
        extRel = 0x1d749d8
        myself = {classId = 36, objectId = 60426032, objectSubId = 60424848}
        extScan = 0x1d9a160
        versionName = 0x1d99740 "2.1.0SVNnext"
        requiredSchemas = <optimized out>
        key = {{sk_flags = 0, sk_attno = 1, sk_strategy = 3, sk_subtype = 0,
            sk_collation = 100, sk_func = {fn_addr = 0x6ad070 <oideq>,
              fn_oid = 184, fn_nargs = 2, fn_strict = 1 '\001',
              fn_retset = 0 '\000', fn_stats = 2 '\002', fn_extra = 0x0,
              fn_mcxt = 0x1d59ec0, fn_expr = 0x0}, sk_argument = 24579}}
        extTup = 0x1da9500
        values = {0, 0, 0, 1, 31040080, 0, 0}
        requiredExtensions = <optimized out>
        nulls = "\000\000\000\000\000\000"
        repl = "\000\000\000\001\001\000"
        lc = <optimized out>
        oldVersionName = 0x39a0290 "2.1.0SVN"
        lcv = 0x1d99908
        __func__ = "ApplyExtensionUpdates"
#4  0x0051640e in ExecAlterExtensionStmt (stmt=0x1d50cc0) at extension.c:2492
        d_new_version = <optimized out>
        versionName = 0x1d50c20 "2.1.0SVNnext"
        oldVersionName = 0x39a0290 "2.1.0SVN"
        control = 0x1d67530
        extensionOid = 24579
        extRel = <optimized out>
        key = {{sk_flags = 0, sk_attno = 1, sk_strategy = 3, sk_subtype = 0,
            sk_collation = 100, sk_func = {fn_addr = 0x6a3e30 <nameeq>,
              fn_oid = 62, fn_nargs = 2, fn_strict = 1 '\001',
              fn_retset = 0 '\000', fn_stats = 2 '\002', fn_extra = 0x0,
              fn_mcxt = 0x1d59ec0, fn_expr = 0x0}, sk_argument = 30739464}}
        extScan = <optimized out>
        extTup = <optimized out>
        updateVersions = <optimized out>
        datum = <optimized out>
        isnull = <optimized out>
        lc = <optimized out>
        __func__ = "ExecAlterExtensionStmt"
#5  0x0065393e in PortalRunUtility (portal=0x1d9ac00, utilityStmt=0x1d50cc0,
    isTopLevel=1 '\001', dest=0x1d50ea8, completionTag=0x1ccf3a4 "")
    at pquery.c:1186
        active_snapshot_set = 1 '\001'
        __func__ = "PortalRunUtility"
#6  0x006543dd in PortalRunMulti (portal=0x1d9ac00, isTopLevel=1 '\001',
    dest=0x1d50ea8, altdest=0x1d50ea8, completionTag=0x1ccf3a4 "")
    at pquery.c:1324
        stmt = 0x1d50cc0
        active_snapshot_set = <optimized out>
        stmtlist_item = 0x1d50e70
#7  0x00655191 in PortalRun (portal=0x1d9ac00, count=2147483647,
    isTopLevel=1 '\001', dest=0x1d50ea8, altdest=0x1d50ea8,
    completionTag=0x1ccf3a4 "") at pquery.c:815
        save_exception_stack = 0x1ccf3e4
        save_context_stack = 0x0
        local_sigjmp_buf = {30208536, 30209060, 31042560, 30208932, 30208364,
          6639617, 30212036, 0, 1447244336, 0, 30208536, 23397311, 2,
          31042560, 30208536, 4215167}
        result = <optimized out>
        nprocessed = <optimized out>
        saveTopTransactionResourceOwner = 0x1d58c60
        saveTopTransactionContext = 0x349c08
        saveActivePortal = 0x0
        saveResourceOwner = 0x1d58c60
        savePortalContext = 0x0
        saveMemoryContext = 0x349c08
        __func__ = "PortalRun"
#8  0x00650d66 in exec_simple_query (
    query_string=0x1d509b0 "ALTER EXTENSION postgis\n  UPDATE TO \"2.1.0SVNnext\
";") at postgres.c:1052
        parsetree = 0x1d50cc0
        portal = 0x1d9ac00
        snapshot_set = 0 '\000'
        commandTag = 0x8c8b9c "ALTER EXTENSION"
        completionTag = "\000ELECT 1\000ôI\001\037\000\000\000.PO\000OóI\001\060
", '\000' <repeats 11 times>, "èóI\001«+_\001\000\000\000\000\000\000\000\000oóI
\001\000\000\000\000\000\000\000"
        querytree_list = <optimized out>
        plantree_list = 0x1d50e88
        receiver = <optimized out>
        format = 0
        dest = DestRemote
        parsetree_list = 0x1d50cf8
        save_log_statement_stats = 0 '\000'
        was_logged = <optimized out>
        msec_str = "\000\000\000\000\b\000\000\000\000\004\000\000K\000\000\000x
üw\000y=\aî\037ôI\001H`_\005"
        parsetree_item = 0x1d50ce0
        isTopLevel = <optimized out>
#9  PostgresMain (argc=2, argv=0x3492f8, username=0x347e10 "postgres")
    at postgres.c:3968
        query_string = 0x1d509b0 "ALTER EXTENSION postgis\n  UPDATE TO \"2.1.0SV
Nnext\";"
        dbname = <optimized out>
        firstchar = 31042560
        input_message = {
          data = 0x1d50190 "ALTER EXTENSION postgis\n  UPDATE TO \"2.1.0SVNnext\
";", len = 52, maxlen = 1024, cursor = 52}
        local_sigjmp_buf = {30209112, 30208868, 3445496, 3440144, 30208540,
          6621139, 30212036, 0, 1447244336, 0, 0, 12, 7911782, 30209112,
          1502717832, 95245}
        send_ready_for_query = 0 '\000'
        __func__ = "PostgresMain"
#10 0x00605aca in BackendRun (port=0x1ccfca8) at postmaster.c:3619
        ac = 2
        secs = 409075662
        usecs = 825352
        i = <optimized out>
        av = 0x3492f8
        maxac = <optimized out>
#11 SubPostmasterMain (argc=3, argv=0x3418c0) at postmaster.c:4120
        port = {sock = 4, noblock = 0 '\000', proto = 196608, laddr = {
            addr = {ss_family = 23, __ss_pad1 = "\025B\000\000\000",
              __ss_align = 0,
              __ss_pad2 = "\000\000\000\000\000\000\000\001", '\000' <repeats 10
3 times>}, salen = 28}, raddr = {addr = {ss_family = 23,
              __ss_pad1 = "x\025\000\000\000", __ss_align = 0,
              __ss_pad2 = "\000\000\000\000\000\000\000\001", '\000' <repeats 10
3 times>}, salen = 28}, remote_host = 0x1cf2c98 "::1",
          remote_hostname = 0x0, remote_hostname_resolv = 0,
          remote_port = 0x1cf2c88 "55061", canAcceptConnections = CAC_OK,
          database_name = 0x347dd8 "testpostgis21",
          user_name = 0x347e10 "postgres", cmdline_options = 0x0,
          guc_options = 0x348328, hba = 0x1d46568, md5Salt = "7§ëF",
          SessionStartTime = 409075662825352, default_keepalives_idle = 0,
          default_keepalives_interval = 0, default_keepalives_count = 0,
          keepalives_idle = 0, keepalives_interval = 0, keepalives_count = 0,
          gss = 0x1cf2c58}
        __func__ = "SubPostmasterMain"
#12 0x00597680 in main (argc=7015, argv=0x3418c0) at main.c:176
No locals.
(gdb)

[robe]

I think Tom might have hit the nail on head. ​http://archives.postgresql.org/pgsql-bugs/2012-12/msg00159.php

"Hm … pg_extension does not have a TOAST table. Could the extconfig and extcondition fields be getting bloated unreasonably? If I understand the scenario here, this would require (1) the extension contains a configuration table (probably one with a filter condition) and (2) for some reason the repeated updates are adding, not replacing, entries for the table in these columns.

If that's the story it would be easy to verify by watching the extension's pg_extension entry as you repeatedly upgrade it."

It's my spatial ref condition that is probably causing this. The extcondition array is increasing 1 each time I run the upgrade.

CREATE EXTENSION postgis;
select array_upper(extcondition,1) from pg_extension where extname = 'postgis';

-- 1

ALTER EXTENSION postgis UPDATE TO "2.1.0SVNnext";

select array_upper(extcondition,1) from pg_extension where extname = 'postgis';

-- 2


ALTER EXTENSION postgis UPDATE TO "2.1.0SVN";

select array_upper(extcondition,1) from pg_extension where extname = 'postgis';

-- 3


ALTER EXTENSION postgis UPDATE TO "2.1.0SVNnext";

ERROR:  row is too big: size 9272, maximum size 8160

[robe]

Okay going to consider this fixed at r10852 for postgis 2.1.0. I still need to make the same change for postgis 2.0 branch.

I was able to make a fake_postgis extension with nothing but the suspect pieces. They are discussing the issue here: ​http://archives.postgresql.org/pgsql-bugs/2012-12/msg00166.php

The fatal mistake I made is that I thought the

spatial_ref_sys WHERE condition I put in:

SELECT pg_catalog.pg_extension_config_dump('spatial_ref_sys',  'WHERE NOT (srid BETWEEN ..')

Needed to prevent spatial_ref_sys records we package from being backed up and thus failing on reinstall, would overwrite the original spatial_ref_sys config_dump entry. Instead it just adds to it and after 3 upgrades (the array exceeds the limit of pg_extension space since pg_extension doesn't have a companion TOAST table to hold the extra load).

I'll upgrade my production system running 2.1.0SVN and if that looks good I'll backport to 2.0.3 and test by upgrading one of my 2.0 installs.

[strk]

Robe: will you complete the task here ? Sounds like partially fixed by the comments above …

[robe]

It's a little late for 2.0.3 no.

[strk]

2.0.3 is out, the question is do you want to do it in the 2.0 branch at all ?

[robe]

I have to otherwise people won't be able to upgrade. I was just debating to go with simple hot fix or longer term solution. I guess I'll go for the hot fix.

[robe]

This was fixed upstream so anyone sitll having the issue recommend to upgrade to latest micro of PostgreSQL.