[GENERAL] explain analyze showed improved results without changes, why?
Howdy. I was noticing a significant problem with a query on one of my tables. I tried recreating the problem and wasn't able to do so on a different install, and so a few days later I ran the same query on the problem table. Lo' and behold, there wasn't a problem anymore. I'm at a loss to why. The indices and two explains follow below. Thanks in advance for the help. Cheers, Chris Indexes: "blocks_pkey" PRIMARY KEY, btree (cloudidx, blkid) "blocks_blkid_idx" btree (blkid) "blocks_cloudidx_idx" btree (cloudidx) "blocks_off_sz_idx" btree (off, sz) mdb=> explain analyze SELECT * FROM blocks WHERE cloudidx=98038 AND off+sz >= 0 AND state='seeded' ORDER BY off LIMIT 1 FOR UPDATE; QUERY PLAN --- Limit (cost=0.43..587.83 rows=1 width=100) (actual time=4814.579..4814.579 rows=1 loops=1) -> LockRows (cost=0.43..1358633.99 rows=2313 width=100) (actual time=4814.577..4814.577 rows=1 loops=1) -> Index Scan using blocks_off_sz_idx on blocks (cost=0.43..1358610.86 rows=2313 width=100) (actual time=4813.498..4814.384 rows=2 loops=1) Filter: ((cloudidx = 98038) AND (state = 'seeded'::block_state) AND ((off + sz) >= 0)) Rows Removed by Filter: 6935023 Total runtime: 4814.619 ms (6 rows) mdb=> select count(*) from blocks; count -- 11052135 (1 row) mdb=> select count (distinct (cloudidx)) from blocks; count --- 4549 (1 row) And here's the second. Notice that even though there are more rows, it was much faster and the "rows removed by filter" were significantly reduced by several orders of magnitude. mdb=> explain analyze SELECT * FROM blocks WHERE cloudidx=98038 AND off+sz >= 0 AND state='seeded' ORDER BY off LIMIT 1 FOR UPDATE; QUERY PLAN- Limit (cost=0.43..584.57 rows=1 width=100) (actual time=0.071..0.071 rows=1 loops=1) -> LockRows (cost=0.43..1390825.21 rows=2381 width=100) (actual time=0.070..0.070 rows=1 loops=1) -> Index Scan using blocks_off_sz_idx on blocks (cost=0.43..1390801.40 rows=2381 width=100) (actual time=0.055..0.055 rows=1 loops=1) Filter: ((cloudidx = 98038) AND (state = 'seeded'::block_state) AND ((off + sz) >= 0)) Rows Removed by Filter: 26 Total runtime: 0.114 ms(6 rows) mdb=> select count(*) from blocks; count-- 11328801(1 row) mdb=> select count (distinct (cloudidx)) from blocks; count--- 4613(1 row)
Re: [GENERAL] LOG: munmap(0x7fff80000000) failed: Invalid argument
I have another application that consumes all of the huge pages; they aren't for pgsql. :) I've modified the configuration file from "try" to "off" and munmap is no more. Mischief managed. Thanks for your help. On Tue, Oct 11, 2016 at 6:15 PM, Tom Lane wrote: > Chris Richards writes: > > Oh the email spam :P > > No problem. I'm starting to think that this isn't actually a Postgres > bug, but rather something funny with your kernel. The code in sysv_shmem > is certainly as fragile as can be, but I'm darned if I can find an > existing code path that would actually break it --- and the lack of other > complaints is pointing towards something funny with your system, too. > > First off, does changing "huge_pages" in postgresql.conf alter the > behavior? (It defaults to "try", see what happens with "on" or "off".) > > Second, I notice that you've got > > > Hugepagesize:1048576 kB > > which is just enormous. PG is only going to request circa 140MB given > the settings you mentioned. We've seen reports of kernel bugs that cause > mmap() to fail for requests that aren't a multiple of the hugepage size, > but I've not heard that mmap() might succeed and then munmap() fail. > That seems like what's happening to you though. > > regards, tom lane >
Re: [GENERAL] LOG: munmap(0x7fff80000000) failed: Invalid argument
Oh the email spam :P I did another reboot test to validate the error. It does exist; it does not spam munmap error like it did with the aptitude install. I then marked the log file, shutdown (1 munmap during), marked it again and then started it (1 munmap during). MARK PRE-SHUTDOWN 2016-10-11 20:02:45 UTC [1656-2] LOG: received fast shutdown request 2016-10-11 20:02:45 UTC [1656-3] LOG: aborting any active transactions 2016-10-11 20:02:45 UTC [1707-2] LOG: autovacuum launcher shutting down 2016-10-11 20:02:45 UTC [1704-1] LOG: shutting down 2016-10-11 20:02:45 UTC [1704-2] LOG: database system is shut down 2016-10-11 20:02:45 UTC [1656-4] LOG: munmap(0x7fff8000) failed: Invalid argument MARK PRE-START 2016-10-11 20:03:02 UTC [9894-1] LOG: database system was shut down at 2016-10-11 20:02:45 UTC 2016-10-11 20:03:02 UTC [9894-2] LOG: MultiXact member wraparound protections are now enabled 2016-10-11 20:03:02 UTC [9893-1] LOG: database system is ready to accept connections 2016-10-11 20:03:02 UTC [9898-1] LOG: autovacuum launcher started 2016-10-11 20:03:02 UTC [9899-1] LOG: munmap(0x7fff8000) failed: Invalid argument 2016-10-11 20:03:02 UTC [9900-1] [unknown]@[unknown] LOG: incomplete startup packet On Mon, Oct 10, 2016 at 5:21 PM, Tom Lane wrote: > Chris Richards writes: > > Setting up postgresql-9.5 (9.5.4-1.pgdg14.04+2) ... > > Creating new cluster 9.5/main ... > > config /etc/postgresql/9.5/main > > data /var/lib/postgresql/9.5/main > > locale en_US.UTF-8 > > LOG: munmap(0x7fff8000) failed: Invalid argument > > [... snip 14 or so repeats ...] > > LOG: munmap(0x7fff8000) failed: Invalid argument > > socket /var/run/postgresql > > port 5433 > > update-alternatives: using > > /usr/share/postgresql/9.5/man/man1/postmaster.1.gz to provide > > /usr/share/man/man1/postmaster.1.gz (postmaster.1.gz) in auto mode > > * Starting PostgreSQL 9.5 database server > > [ OK ] > > Processing triggers for libc-bin (2.19-0ubuntu6.6) ... > > > I'm able to connect and I dumped a few default relations. > > > Is the munmap error of concern? It remains upon rebooting / restarting > the > > server. > > Seems pretty fishy to me; I don't know what would be causing it. > > [ digs in code... ] One theory is that PGSharedMemoryDetach is getting > called more than once, but I'm not sure how that would happen. Can you > characterize where this happens more precisely? What nondefault settings > have you got in postgresql.conf? > > regards, tom lane >
Re: [GENERAL] LOG: munmap(0x7fff80000000) failed: Invalid argument
One extra bit, if this helps: chrisr@ff1:~$ cat /proc/meminfo MemTotal:8163104 kB MemFree: 2183692 kB MemAvailable:3648680 kB Buffers: 170080 kB Cached: 1231708 kB SwapCached:0 kB Active: 1083596 kB Inactive: 442312 kB Active(anon): 125128 kB Inactive(anon): 3584 kB Active(file): 958468 kB Inactive(file): 438728 kB Unevictable: 0 kB Mlocked: 0 kB SwapTotal:499708 kB SwapFree: 499708 kB Dirty: 0 kB Writeback: 0 kB AnonPages:124124 kB Mapped:42472 kB Shmem: 4596 kB Slab: 144788 kB SReclaimable: 97612 kB SUnreclaim:47176 kB KernelStack: 10672 kB PageTables: 6332 kB NFS_Unstable: 0 kB Bounce:0 kB WritebackTmp: 0 kB CommitLimit: 2484108 kB Committed_AS: 900632 kB VmallocTotal: 34359738367 kB VmallocUsed: 202276 kB VmallocChunk: 34359464540 kB HardwareCorrupted: 0 kB AnonHugePages: 0 kB HugePages_Total: 4 HugePages_Free:3 HugePages_Rsvd:0 HugePages_Surp:0 Hugepagesize:1048576 kB DirectMap4k: 83776 kB DirectMap2M: 4110336 kB DirectMap1G: 6291456 kB On Mon, Oct 10, 2016 at 5:21 PM, Tom Lane wrote: > Chris Richards writes: > > Setting up postgresql-9.5 (9.5.4-1.pgdg14.04+2) ... > > Creating new cluster 9.5/main ... > > config /etc/postgresql/9.5/main > > data /var/lib/postgresql/9.5/main > > locale en_US.UTF-8 > > LOG: munmap(0x7fff8000) failed: Invalid argument > > [... snip 14 or so repeats ...] > > LOG: munmap(0x7fff8000) failed: Invalid argument > > socket /var/run/postgresql > > port 5433 > > update-alternatives: using > > /usr/share/postgresql/9.5/man/man1/postmaster.1.gz to provide > > /usr/share/man/man1/postmaster.1.gz (postmaster.1.gz) in auto mode > > * Starting PostgreSQL 9.5 database server > > [ OK ] > > Processing triggers for libc-bin (2.19-0ubuntu6.6) ... > > > I'm able to connect and I dumped a few default relations. > > > Is the munmap error of concern? It remains upon rebooting / restarting > the > > server. > > Seems pretty fishy to me; I don't know what would be causing it. > > [ digs in code... ] One theory is that PGSharedMemoryDetach is getting > called more than once, but I'm not sure how that would happen. Can you > characterize where this happens more precisely? What nondefault settings > have you got in postgresql.conf? > > regards, tom lane >
Re: [GENERAL] LOG: munmap(0x7fff80000000) failed: Invalid argument
What more would you like--I'm happy to oblige? The upgrade steps I listed installed into a new directory, new conf file. I didn't even migrate my (skeletal) 9.3 database. Here's the 9.5 command-line. I've attached the referenced config file. $ chrisr@ff1:~$ ps ax | grep bin/post 10 ?S 0:00 /usr/lib/postgresql/9.5/bin/postgres -D /var/lib/postgresql/9.5/main -c config_file=/etc/postgresql/9.5/main/postgresql.conf Cheers, Chris On Mon, Oct 10, 2016 at 5:21 PM, Tom Lane wrote: > Chris Richards writes: > > Setting up postgresql-9.5 (9.5.4-1.pgdg14.04+2) ... > > Creating new cluster 9.5/main ... > > config /etc/postgresql/9.5/main > > data /var/lib/postgresql/9.5/main > > locale en_US.UTF-8 > > LOG: munmap(0x7fff8000) failed: Invalid argument > > [... snip 14 or so repeats ...] > > LOG: munmap(0x7fff8000) failed: Invalid argument > > socket /var/run/postgresql > > port 5433 > > update-alternatives: using > > /usr/share/postgresql/9.5/man/man1/postmaster.1.gz to provide > > /usr/share/man/man1/postmaster.1.gz (postmaster.1.gz) in auto mode > > * Starting PostgreSQL 9.5 database server > > [ OK ] > > Processing triggers for libc-bin (2.19-0ubuntu6.6) ... > > > I'm able to connect and I dumped a few default relations. > > > Is the munmap error of concern? It remains upon rebooting / restarting > the > > server. > > Seems pretty fishy to me; I don't know what would be causing it. > > [ digs in code... ] One theory is that PGSharedMemoryDetach is getting > called more than once, but I'm not sure how that would happen. Can you > characterize where this happens more precisely? What nondefault settings > have you got in postgresql.conf? > > regards, tom lane > postgresql.conf Description: Binary data -- Sent via pgsql-general mailing list (pgsql-general@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-general
[GENERAL] LOG: munmap(0x7fff80000000) failed: Invalid argument
Howdy. I have an Ubuntu 14.04 LTS, configured with huge pages (4x1GB, disabled transparent) and a later kernel than what ships with 14.04. root@ff2:~# uname -a Linux ff2 3.16.7-ckt11-061515+ #1 SMP Mon Jun 15 18:47:13 CDT 2015 x86_64 x86_64 x86_64 GNU/Linux It had postgresql-9.3 on it and I installed postgresql-9.5 via these steps: aptitude remove -y postgresql-9.3 echo "deb http://apt.postgresql.org/pub/repos/apt/ trusty-pgdg main 9.5" > /etc/apt/sources.list.d/postgresql.list apt-key adv --keyserver keyserver.ubuntu.com --recv-keys 7FCC7D46ACCC4CF8 apt-get update apt-get install -y postgresql-client-9.5 postgresql-common postgresql-9.5 At the end of the install, these were emitted to the screen: Setting up postgresql-9.5 (9.5.4-1.pgdg14.04+2) ... Creating new cluster 9.5/main ... config /etc/postgresql/9.5/main data /var/lib/postgresql/9.5/main locale en_US.UTF-8 LOG: munmap(0x7fff8000) failed: Invalid argument [... snip 14 or so repeats ...] LOG: munmap(0x7fff8000) failed: Invalid argument socket /var/run/postgresql port 5433 update-alternatives: using /usr/share/postgresql/9.5/man/man1/postmaster.1.gz to provide /usr/share/man/man1/postmaster.1.gz (postmaster.1.gz) in auto mode * Starting PostgreSQL 9.5 database server [ OK ] Processing triggers for libc-bin (2.19-0ubuntu6.6) ... I'm able to connect and I dumped a few default relations. Is the munmap error of concern? It remains upon rebooting / restarting the server. Thanks, Chris
Re: [GENERAL] What could cause CREATE TEMP... "could not read block" error?
> Are you running the latest minor release for your PostgreSQL version? No. 9.3.9 whereas the lastest is 9.3.10 > Were there any crashes recently? No[*]. See comments below about LVM snapshots. > Do you have "fsync = on"? Yes. > Did you make sure that you have a reliable storage system? RAID-6 SSDs on ext4 I've observed the problem on other than the "pg_depend" table. A normal table (called "blocks") had the problem. A "REINDEX TABLE blocks" did not fix the problem, however a "VACUUM FULL" did "fix" it. We had thought we figured out what might have caused the problem. We were taking LVM snapshots while the database was running and then at sometime later we reverted the snapshot (while postgres was stopped). Our theory was that since postgres was running and therefore we captured its backing store in an indeterminate state. We changed our snapshot process to shutdown postgres, take the LVM snapshot, and then start postgres. Unfortunately, the problem cropped up again. We had an empty database except for our created tables, took the snapshot, and then populated the tables using normal INSERT/UPDATE/DELETEs while the system ran. Then, we reboot and revert the LVM snapshot--back to the empty database. We then populated the tables by using a series "COPY FROM ". The only things special about this is we dropped one foreign key constraint and that with our data files is that we may issue back-to-back COPY's to the same table (each COPY pulling in different data as we pre-process the data before COPY'ing it). The amount of data is relatively small from our COPY's: dirtable - 1 row dirpath - 1 row cloud - 940 rows blocks - 176 rows (before it died) Indexes were not disabled during the bulk import. Chris On Mon, Nov 23, 2015 at 2:59 AM, Albe Laurenz wrote: > Chris Richards wrote: > > Adrian is correct. This worked by itself whereas using it in the > creation of the temporary table > > failed. > > mdb-> SELECT pq.* FROM policyqueue AS pq > > mdb-> JOIN seed_progress AS sp ON pq.id <http://pq.id/> =sp.polidx; > > > > I checked the query Albe suggested; there were two `relfilenode`s (11936 > and 11937) that exhibited the > > error. Respectively, they were pg_depend_depender_index and > pg_depend_reference_index. > > > > Unfortunately, I didn't disable the nightly processes and something > must have(?) fixed the glitch; at > > midnight GMT the query ran successfully. Ugh. > > > > If it crops up again, I have some tools to try and capture data > immediately, and the suggested REINDEX > > since both appear to be indices. > > These indexes are both on the system table "pg_depend". > > That explains why the query ran without problems but the CREATE TABLE > didn't: > Creating an object creates dependencies, and you have data corruption in > the > system table that tracks dependencies. > > I would be pretty worried in your place if I had a corrupted catalog, even > if > it seems to have "fixed itself". There might be other tables with > corruption. > > I would do two things: > 1) Wait for a moment when there is little database traffic and >run "REINDEX TABLE pg_depend;" to rebuild these indexes. > > 2) As soon as you can schedule some downtime, pg_dumpall the database >cluster, stop the server, throw away the database cluster, create a new >one with "initdb" and restore the dump into that. >That will get rid of any lurking data corruption. >Watch out for error messages during the pg_dumpall! > > > The main question is of course how you got the corruption in the first > place. > Are you running the latest minor release for your PostgreSQL version? > Were there any crashes recently? > Do you have "fsync = on"? > Did you make sure that you have a reliable storage system? > > Yours, > Laurenz Albe >
Re: [GENERAL] What could cause CREATE TEMP... "could not read block" error?
Adrian is correct. This worked by itself whereas using it in the creation of the temporary table failed. mdb-> SELECT pq.* FROM policyqueue AS pq mdb-> JOIN seed_progress AS sp ON pq.id=sp.polidx; I checked the query Albe suggested; there were two `relfilenode`s (11936 and 11937) that exhibited the error. Respectively, they were pg_depend_depender_index and pg_depend_reference_index. Unfortunately, I didn't disable the nightly processes and something must have(?) fixed the glitch; at midnight GMT the query ran successfully. Ugh. If it crops up again, I have some tools to try and capture data immediately, and the suggested REINDEX since both appear to be indices. Thanks for the help. It's appreciated. Chris On Fri, Nov 20, 2015 at 8:28 AM, Adrian Klaver wrote: > On 11/20/2015 06:18 AM, Albe Laurenz wrote: > >> Chris Richards wrote: >> >>> Howdy. I have two tables that I'm joining together and using the result >>> to create a temporary table. >>> Performing the join operation works fine; it produces 0 rows (as >>> expected). If I prepend "CREATE TEMP >>> tmp_policyqueue AS" to the SELECT then it generates this error: >>> >>> ERROR: could not read block 39 in file "base/16391/11937": read only 0 >>> of 8192 bytes >>> >>> >>> $ psql >>> psql (9.3.9) >>> >>> mdb=> CREATE TEMP TABLE tmp_policyqueue AS >>> >>> mdb-> SELECT pq.* FROM policyqueue AS pq >>> mdb-> JOIN seed_progress AS sp ON pq.id=sp.polidx; >>> ERROR: could not read block 40 in file "base/16391/11937": read only 0 >>> of 8192 bytes >>> >>> You'll also observe that the block number is changing each time I >>> execute the command. I know very >>> little about postgres internal structure so it may be irrelevant. I've >>> left my database in this state >>> should extra information be needed. >>> >> >> It would be interesting to know what object is affected: >> >> SELECT s.nspname AS schemaname, t.relname AS objectname, t.relkind >> FROM pg_class t JOIN >> pg_namespace s ON t.relnamespace = s.oid >> WHERE t.relfilenode = 11937; >> >> If it is an index, REINDEX should help. >> >> What is the statement that performs the join operation and works just >> fine? >> > > If I am following correctly it is: > > mdb-> SELECT pq.* FROM policyqueue AS pq > mdb-> JOIN seed_progress AS sp ON pq.id=sp.polidx; > > >> Yours, >> Laurenz Albe >> >> > > -- > Adrian Klaver > adrian.kla...@aklaver.com >
[GENERAL] What could cause CREATE TEMP... "could not read block" error?
Howdy. I have two tables that I'm joining together and using the result to create a temporary table. Performing the join operation works fine; it produces 0 rows (as expected). If I prepend "CREATE TEMP tmp_policyqueue AS" to the SELECT then it generates this error: ERROR: could not read block 39 in file "base/16391/11937": read only 0 of 8192 bytes $ psql psql (9.3.9) mdb=> CREATE TEMP TABLE tmp_policyqueue AS mdb-> SELECT pq.* FROM policyqueue AS pq mdb-> JOIN seed_progress AS sp ON pq.id=sp.polidx; ERROR: could not read block 40 in file "base/16391/11937": read only 0 of 8192 bytes You'll also observe that the block number is changing each time I execute the command. I know very little about postgres internal structure so it may be irrelevant. I've left my database in this state should extra information be needed. Thanks for any assist. Chris
