Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1u1rrJ-009MgG-08 for pgsql-hackers@arkaria.postgresql.org; Mon, 07 Apr 2025 19:10:13 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.94.2) (envelope-from ) id 1u1rrF-002ot3-Po for pgsql-hackers@arkaria.postgresql.org; Mon, 07 Apr 2025 19:10:10 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1u1rrF-002osv-DP for pgsql-hackers@lists.postgresql.org; Mon, 07 Apr 2025 19:10:09 +0000 Received: from mail-lj1-x22c.google.com ([2a00:1450:4864:20::22c]) by magus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 (Exim 4.96) (envelope-from ) id 1u1rrA-003yVp-2d for pgsql-hackers@postgresql.org; Mon, 07 Apr 2025 19:10:07 +0000 Received: by mail-lj1-x22c.google.com with SMTP id 38308e7fff4ca-30db1bd3bebso42634571fa.2 for ; Mon, 07 Apr 2025 12:10:04 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20230601; t=1744053003; x=1744657803; darn=postgresql.org; h=in-reply-to:from:content-language:references:cc:to:subject :user-agent:mime-version:date:message-id:from:to:cc:subject:date :message-id:reply-to; bh=px7K+oXgsvgo80XQtfGVHh9/EXl7EDc0UnGL+xqsVPA=; b=WesHhkLNS8f/XanB9j+Z8a19EItP9X6+mA56Twl5KKVFFGWAn7+h4vxcCyAOYCTxV7 Ql5ZBFIvZY9CQMh6iadgW3oyfUcTLQ5qYcNOyS4RmR8319E9mFteugn1R9yRuDzfqwUn mBZFi6Z/dntHeXZqCHCSlrxVMLDq8MxMKd4EUyYUP8Xd6tj5lRBc7pu0QP3p3NlGYisE glXDz58CE9IemHT5ZxcjsYLIeUt1YDFlnh8kzzmzE74OjIaUDS6ey7dexwdEzLmZt+9G 725e5zuemrHpY1uPplYvCpCVHcReVVPTGA/DbLlogW8sbfsH4s/L3lFhFIMTQMB/ke+H 8b8w== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1744053003; x=1744657803; h=in-reply-to:from:content-language:references:cc:to:subject :user-agent:mime-version:date:message-id:x-gm-message-state:from:to :cc:subject:date:message-id:reply-to; bh=px7K+oXgsvgo80XQtfGVHh9/EXl7EDc0UnGL+xqsVPA=; b=phyUlIcLyzrEzw1FRd/HxPgUt2fS4xPFML+US8c7k0x6qRm9S28kaSTeu7dnrnB01G H/6/29H5zzjQAWgfSezkfnkF0ejrnr8xSnm0eOO+HF5nDQWeen+5SxqOH9p72uQeF2KB Ng3hydGvjUqZIMVHNzB//AHfNEJRBd5oke0wAfixMeKaYUVOccvbSRyp4LVbIUAsjrWM t0bOVbjFyy7hZ2istYytUoxYqsQ8o7EdhrH8BxmCIHqsD1N9yFqjuKJRXK1mYhcCrFpF R2dDCImZmY7xqnGeG/KhP9UAXuhrtE7Lxn+C4IzzuMKOogCUTt37FwRp4aUA+D2zmZdI 8FOQ== X-Forwarded-Encrypted: i=1; AJvYcCXlJ39ZFscRXfasfaOt0MXPgUotO1twN/jhZEWjQFI+AKB8iOyPcUnxPww9N5fbdkX3ZiBFZqIq647OomJE@postgresql.org X-Gm-Message-State: AOJu0YynLyP9A9tFtTbXdKNeRZNloixLIifhP6N1W+T9xmzq1gtbNZ4P wzTC3SownQx/d62qOOhhCU4IEFwkN62m+mivTbMBg1ygzdYOj1Ph X-Gm-Gg: ASbGncuuDW7zyjXQ3VTCNqzFW61iiBkkzLafSyF9G3EUiYX/cs5p+raR5qGGn424txL 9WTogaaXpRIvd559X4btVFGRrflWOgGpIha7ECuep1VUZwaTnFpMmMB7ZcvX+ZbLvB17IHFOIXl 3IKYLL8HO9akhUVjjdZRkgFhFs+k93mc1WCZ/1xZZJ3zxI+s9mprvlz5UBwBv59itNrrk9Wl2QW Y5fSVt3onv8cemLMGBuvoET3bxQBorHYonEV6F2niQSAdHd60nCPSygowEyiePI99jW9RAcitRA IVRaQN+KrQtI7R85Xey0Pcd7agQ8S1g7ZJXHFlsD+hj1gOw= X-Google-Smtp-Source: AGHT+IH8dtrzurOinNgWEpq93CNsuA0foc4fcHG82j66hu+Yuhi9vhA8YdH50LkFkgGuPCgrnOU76g== X-Received: by 2002:a05:651c:220a:b0:30a:4428:dea9 with SMTP id 38308e7fff4ca-30f0a1817a9mr46031801fa.30.1744053002749; Mon, 07 Apr 2025 12:10:02 -0700 (PDT) Received: from [192.168.0.50] ([89.149.68.176]) by smtp.gmail.com with ESMTPSA id 38308e7fff4ca-30f031245e4sm16745111fa.2.2025.04.07.12.10.01 (version=TLS1_3 cipher=TLS_AES_128_GCM_SHA256 bits=128/128); Mon, 07 Apr 2025 12:10:02 -0700 (PDT) Content-Type: multipart/alternative; boundary="------------U1NcQLS9BGVZnYGPQRcTfHTR" Message-ID: <6a6756a0-bad5-4ee5-a591-c763af289940@gmail.com> Date: Mon, 7 Apr 2025 22:10:01 +0300 MIME-Version: 1.0 User-Agent: Mozilla Thunderbird Subject: Re: AIO v2.5 To: Andres Freund Cc: Noah Misch , pgsql-hackers@postgresql.org, Thomas Munro , Heikki Linnakangas , Robert Haas , Jakub Wartak , Jelte Fennema-Nio , Antonin Houska References: <20250329212929.a6.nmisch@google.com> <7s6fclfekpcxoaaorwrq67v4vmgixf2dcjcgznuj7vxs3ie3wq@okqbi5vabqbx> <20250401151159.51.nmisch@google.com> <20250402001324.e4.nmisch@google.com> <3fhulsvzks4khqahl6tngcnuda7pyrrl7223tmjh2x2spralm3@iisldh6pcowy> <8160688e-db8e-4d7d-a7e7-ff366adf9717@gmail.com> <4nervqmqplfr23jrjvkp5tsumi6qgouhgjqlubf7ujrudw2epb@6mszddainl4u> Content-Language: en-US From: Alexander Lakhin In-Reply-To: <4nervqmqplfr23jrjvkp5tsumi6qgouhgjqlubf7ujrudw2epb@6mszddainl4u> List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk This is a multi-part message in MIME format. --------------U1NcQLS9BGVZnYGPQRcTfHTR Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 8bit Hello Andres, 07.04.2025 19:20, Andres Freund wrote: >> iteration 8: Sun Apr  6 19:22:39 UTC 2025 >> installchecks finished: Sun Apr  6 19:23:47 UTC 2025 >> 2025-04-06 19:22:44.216 UTC [349525] LOG:  could not read blocks 0..0 in file "base/6179194/2606": Operation canceled >> 2025-04-06 19:22:44.216 UTC [349525] ERROR:  could not read blocks 0..0 in file "base/6179194/2606": Operation canceled > Thanks for the report, clearly something isn't right. Thank you for your attention to it! >> It's reproduced better on tmpfs for me; probably you would need to increase >> NUM_INSTALLCHECKS/NUM_ITERATIONS for your machine. > I ran it for a while in a VM, it hasn't triggered yet. Neither on xfs nor on > tmpfs. Before sharing the script I tested it on two my machines, but I had anticipated that the error can be hard to reproduce. Will try to reduce the reproducer... >> server.log contains: >> 2025-04-06 19:22:44.215 UTC [38231] LOG:  checkpoint complete: wrote ... >> 2025-04-06 19:22:44.216 UTC [38231] LOG:  checkpoint starting: immediate force wait flush-all >> 2025-04-06 19:22:44.216 UTC [349525] LOG:  could not read blocks 0..0 in file "base/6179194/2606": Operation canceled >> 2025-04-06 19:22:44.216 UTC [349525] STATEMENT:  alter table parted_copytest >> attach partition parted_copytest_a1 for values in(1); >> 2025-04-06 19:22:44.216 UTC [349525] ERROR:  could not read blocks 0..0 in file "base/6179194/2606": Operation canceled >> 2025-04-06 19:22:44.216 UTC [349525] STATEMENT:  alter table parted_copytest >> attach partition parted_copytest_a1 for values in(1); > Hm. Does the failure vary between occurrences? > - is it always the same statement? Probably not? > - is it always 2606 (i.e. pg_constraint)? > - does the failure always happen around a checkpoint? If so, is it always > immediate? > - I do assume it's always ECANCELED? I've got three such failures with three runs of of the script to answer your questions: ... iteration 6: Mon Apr  7 18:08:35 UTC 2025 installchecks finished: Mon Apr  7 18:09:45 UTC 2025 2025-04-07 18:08:45.369 UTC [1941260] LOG:  could not read blocks 7..7 in file "base/4448730/1255": Operation canceled 2025-04-07 18:08:45.369 UTC [1941260] ERROR:  could not read blocks 7..7 in file "base/4448730/1255": Operation canceled server.log: ... 2025-04-07 18:08:44.120 UTC [1713945] LOG:  checkpoint starting: wal 2025-04-07 18:08:45.369 UTC [1941260] LOG:  could not read blocks 7..7 in file "base/4448730/1255": Operation canceled 2025-04-07 18:08:45.369 UTC [1941260] STATEMENT:  SELECT routine_name, ordinal_position, parameter_name, parameter_default         FROM information_schema.parameters JOIN information_schema.routines USING (specific_schema, specific_name)         WHERE routine_schema = 'temp_func_test' AND routine_name ~ '^functest_is_'         ORDER BY 1, 2; 2025-04-07 18:08:45.369 UTC [1941260] ERROR:  could not read blocks 7..7 in file "base/4448730/1255": Operation canceled 2025-04-07 18:08:45.369 UTC [1941260] STATEMENT:  SELECT routine_name, ordinal_position, parameter_name, parameter_default         FROM information_schema.parameters JOIN information_schema.routines USING (specific_schema, specific_name)         WHERE routine_schema = 'temp_func_test' AND routine_name ~ '^functest_is_'         ORDER BY 1, 2; ... 2025-04-07 18:08:51.836 UTC [1713945] LOG:  checkpoint complete: wrote 1558 buffers (9.5%), wrote 22 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=7.544 s, sync=0.019 s, total=7.720 s; sync files=0, longest=0.000 s, average=0.000 s; distance=533837 kB, estimate=533837 kB; lsn=C/E532D478, redo lsn=C/C7054358 ... --- iteration 8: Mon Apr  7 18:26:47 UTC 2025 installchecks finished: Mon Apr  7 18:27:59 UTC 2025 2025-04-07 18:26:53.252 UTC [2359398] LOG:  could not read blocks 0..12 in file "base/4/1255": Operation canceled 2025-04-07 18:26:53.255 UTC [2359398] ERROR:  could not read blocks 0..12 in file "base/4/1255": Operation canceled server.log: ... 2025-04-07 18:26:53.249 UTC [2048053] LOG:  checkpoint complete: wrote 3061 buffers (18.7%), wrote 3 SLRU buffers; 0 WAL file(s) added, 2 removed, 0 recycled; write=0.051 s, sync=0.002 s, total=0.068 s; sync files=0, longest=0.000 s, average=0.000 s; distance=18937 kB, estimate=120161 kB; lsn=11/6D42ED30, redo lsn=11/6C17AC30 2025-04-07 18:26:53.251 UTC [2359308] WARNING:  "most_common_elems" must be specified when "most_common_elem_freqs" is specified 2025-04-07 18:26:53.251 UTC [2359351] WARNING: "elem_count_histogram" array cannot contain NULL values 2025-04-07 18:26:53.252 UTC [2359375] ERROR:  cannot modify statistics for relation "testseq" 2025-04-07 18:26:53.252 UTC [2359375] DETAIL:  This operation is not supported for sequences. 2025-04-07 18:26:53.252 UTC [2359375] STATEMENT:  SELECT pg_catalog.pg_restore_relation_stats(             'schemaname', 'stats_import',             'relname', 'testseq'); 2025-04-07 18:26:53.252 UTC [2359375] ERROR:  cannot modify statistics for relation "testseq" 2025-04-07 18:26:53.252 UTC [2359375] DETAIL:  This operation is not supported for sequences. 2025-04-07 18:26:53.252 UTC [2359375] STATEMENT:  SELECT pg_catalog.pg_clear_relation_stats(schemaname => 'stats_import', relname => 'testseq'); 2025-04-07 18:26:53.252 UTC [2359398] LOG:  could not read blocks 0..12 in file "base/4/1255": Operation canceled 2025-04-07 18:26:53.252 UTC [2359398] STATEMENT:  CREATE DATABASE regress020_tbd         ENCODING utf8 LC_COLLATE "C" LC_CTYPE "C" TEMPLATE template0; 2025-04-07 18:26:53.255 UTC [2359449] ERROR:  invalid input syntax for type pg_snapshot: "31:12:" at character 8 2025-04-07 18:26:53.255 UTC [2359449] STATEMENT:  select '31:12:'::pg_snapshot; 2025-04-07 18:26:53.255 UTC [2359449] ERROR:  invalid input syntax for type pg_snapshot: "0:1:" at character 8 2025-04-07 18:26:53.255 UTC [2359449] STATEMENT:  select '0:1:'::pg_snapshot; 2025-04-07 18:26:53.255 UTC [2359449] ERROR:  invalid input syntax for type pg_snapshot: "12:13:0" at character 8 2025-04-07 18:26:53.255 UTC [2359449] STATEMENT:  select '12:13:0'::pg_snapshot; 2025-04-07 18:26:53.255 UTC [2359449] ERROR:  invalid input syntax for type pg_snapshot: "12:16:14,13" at character 8 2025-04-07 18:26:53.255 UTC [2359449] STATEMENT:  select '12:16:14,13'::pg_snapshot; 2025-04-07 18:26:53.255 UTC [2359398] ERROR:  could not read blocks 0..12 in file "base/4/1255": Operation canceled 2025-04-07 18:26:53.255 UTC [2359398] STATEMENT:  CREATE DATABASE regress020_tbd         ENCODING utf8 LC_COLLATE "C" LC_CTYPE "C" TEMPLATE template0; ... --- iteration 2: Mon Apr  7 19:02:57 UTC 2025 installchecks finished: Mon Apr  7 19:04:07 UTC 2025 2025-04-07 19:03:02.133 UTC [3537488] LOG:  could not read blocks 0..0 in file "base/902183/2607": Operation canceled 2025-04-07 19:03:02.133 UTC [3537488] ERROR:  could not read blocks 0..0 in file "base/902183/2607": Operation canceled server.log: 2025-04-07 19:03:02.129 UTC [3487651] LOG:  checkpoint complete: wrote 337 buffers (2.1%), wrote 2 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.013 s, sync=0.001 s, total=0.024 s; sync files=0, longest=0.000 s, average=0.000 s; distance=2555 kB, estimate=293963 kB; lsn=2/9D3DECE8, redo lsn=2/9D2AAC00 2025-04-07 19:03:02.129 UTC [3537184] ERROR:  invalid regular expression: invalid backreference number 2025-04-07 19:03:02.129 UTC [3537184] STATEMENT:  select 'xyz' ~ 'x(\w)(?=(\1))'; 2025-04-07 19:03:02.129 UTC [3537184] ERROR:  invalid regular expression: invalid escape \ sequence 2025-04-07 19:03:02.129 UTC [3537184] STATEMENT:  select 'a' ~ '\x7fffffff'; 2025-04-07 19:03:02.130 UTC [3537651] ERROR:  operator does not exist: point = box at character 23 2025-04-07 19:03:02.130 UTC [3537651] HINT:  No operator matches the given name and argument types. You might need to add explicit type casts. 2025-04-07 19:03:02.130 UTC [3537651] STATEMENT:  select '(0,0)'::point in ('(0,0,0,0)'::box, point(0,0)); 2025-04-07 19:03:02.133 UTC [3537362] ERROR:  invalid regular expression: invalid backreference number 2025-04-07 19:03:02.133 UTC [3537362] STATEMENT:  select 'xyz' ~ 'x(\w)(?=\1)'; 2025-04-07 19:03:02.133 UTC [3537362] ERROR:  invalid regular expression: invalid backreference number 2025-04-07 19:03:02.133 UTC [3537362] STATEMENT:  select 'xyz' ~ 'x(\w)(?=(\1))'; 2025-04-07 19:03:02.133 UTC [3537362] ERROR:  invalid regular expression: invalid escape \ sequence 2025-04-07 19:03:02.133 UTC [3537362] STATEMENT:  select 'a' ~ '\x7fffffff'; 2025-04-07 19:03:02.133 UTC [3537488] LOG:  could not read blocks 0..0 in file "base/902183/2607": Operation canceled 2025-04-07 19:03:02.133 UTC [3537488] STATEMENT:  SELECT p1.oid, p1.proname     FROM pg_proc as p1     WHERE 'cstring'::regtype = ANY (p1.proargtypes)         AND NOT EXISTS(SELECT 1 FROM pg_type WHERE typinput = p1.oid)         AND NOT EXISTS(SELECT 1 FROM pg_conversion WHERE conproc = p1.oid)         AND p1.oid != 'shell_in(cstring)'::regprocedure     ORDER BY 1; 2025-04-07 19:03:02.133 UTC [3537488] ERROR:  could not read blocks 0..0 in file "base/902183/2607": Operation canceled 2025-04-07 19:03:02.133 UTC [3537488] STATEMENT:  SELECT p1.oid, p1.proname     FROM pg_proc as p1     WHERE 'cstring'::regtype = ANY (p1.proargtypes)         AND NOT EXISTS(SELECT 1 FROM pg_type WHERE typinput = p1.oid)         AND NOT EXISTS(SELECT 1 FROM pg_conversion WHERE conproc = p1.oid)         AND p1.oid != 'shell_in(cstring)'::regprocedure     ORDER BY 1; 2025-04-07 19:03:02.135 UTC [3537671] WARNING:  TIME(7) WITH TIME ZONE precision reduced to maximum allowed, 6 2025-04-07 19:03:02.135 UTC [3537671] WARNING:  TIMESTAMP(7) WITH TIME ZONE precision reduced to maximum allowed, 6 2025-04-07 19:03:02.135 UTC [3537671] WARNING:  TIME(7) precision reduced to maximum allowed, 6 2025-04-07 19:03:02.136 UTC [3487651] LOG:  checkpoint starting: immediate force wait ... So I suspect checkpointer, but I'm not sure yet. (Sometimes (2 out of 5 runs) 10 iterations pass without the error.) That script  with s/grep 'could not read blocks '/grep 'was terminated '/ also discovers another anomaly (right now on the third run, with 10 iterations of 30 installchecks): Core was generated by `postgres: postgres regress005 [local] SELECT                  '. Program terminated with signal SIGSEGV, Segmentation fault. #0  0x0000000000000000 in ?? () (gdb) bt #0  0x0000000000000000 in ?? () #1  0x0000591086d5ccfa in pgaio_io_get_target_description (ioh=ioh@entry=0x7ffcf961bc20) at aio_target.c:85 #2  0x0000591086d5bfdd in pg_get_aios (fcinfo=) at aio_funcs.c:218 #3  0x0000591086bb64c1 in ExecMakeTableFunctionResult (setexpr=0x5910bddcbf48, econtext=0x5910bddcbde8, argContext=,     expectedDesc=0x5910bddff918, randomAccess=false) at execSRF.c:234 #4  0x0000591086bc9673 in FunctionNext (node=node@entry=0x5910bddcbbd8) at nodeFunctionscan.c:94 #5  0x0000591086bb7093 in ExecScanFetch (recheckMtd=0x591086bc9522 , accessMtd=0x591086bc95a2 , epqstate=0x0,     node=0x5910bddcbbd8) at ../../../src/include/executor/execScan.h:126 #6  ExecScanExtended (projInfo=0x0, qual=0x0, epqstate=0x0, recheckMtd=0x591086bc9522 , accessMtd=0x591086bc95a2 ,     node=0x5910bddcbbd8) at ../../../src/include/executor/execScan.h:170 #7  ExecScan (node=0x5910bddcbbd8, accessMtd=accessMtd@entry=0x591086bc95a2 , recheckMtd=recheckMtd@entry=0x591086bc9522 )     at execScan.c:59 #8  0x0000591086bc9580 in ExecFunctionScan (pstate=) at nodeFunctionscan.c:269 #9  0x0000591086bb38f3 in ExecProcNodeFirst (node=0x5910bddcbbd8) at execProcnode.c:469 #10 0x0000591086bc0195 in ExecProcNode (node=0x5910bddcbbd8) at ../../../src/include/executor/executor.h:341 #11 0x0000591086bc021b in fetch_input_tuple (aggstate=aggstate@entry=0x5910bddcb480) at nodeAgg.c:563 #12 0x0000591086bc3825 in agg_retrieve_direct (aggstate=aggstate@entry=0x5910bddcb480) at nodeAgg.c:2450 #13 0x0000591086bc3a19 in ExecAgg (pstate=) at nodeAgg.c:2265 #14 0x0000591086bb38f3 in ExecProcNodeFirst (node=0x5910bddcb480) at execProcnode.c:469 #15 0x0000591086baac23 in ExecProcNode (node=node@entry=0x5910bddcb480) at ../../../src/include/executor/executor.h:341 #16 0x0000591086baacd0 in ExecutePlan (queryDesc=queryDesc@entry=0x5910bdde0e00, operation=operation@entry=CMD_SELECT, sendTuples=sendTuples@entry=true,     numberTuples=numberTuples@entry=0, direction=direction@entry=ForwardScanDirection, dest=dest@entry=0x5910bddf6070) at execMain.c:1783 #17 0x0000591086bab79d in standard_ExecutorRun (queryDesc=0x5910bdde0e00, direction=ForwardScanDirection, count=0) at execMain.c:435 #18 0x0000591086bab7e0 in ExecutorRun (queryDesc=queryDesc@entry=0x5910bdde0e00, direction=direction@entry=ForwardScanDirection, count=count@entry=0)     at execMain.c:371 #19 0x0000591086da9e9f in PortalRunSelect (portal=portal@entry=0x5910bdd72f10, forward=forward@entry=true, count=0, count@entry=9223372036854775807,     dest=dest@entry=0x5910bddf6070) at pquery.c:953 #20 0x0000591086dab83b in PortalRun (portal=portal@entry=0x5910bdd72f10, count=count@entry=9223372036854775807, isTopLevel=isTopLevel@entry=true,     dest=dest@entry=0x5910bddf6070, altdest=altdest@entry=0x5910bddf6070, qc=qc@entry=0x7ffcf961c9f0) at pquery.c:797 #21 0x0000591086da74a4 in exec_simple_query (query_string=query_string@entry=0x5910bdcebe60 "SELECT COUNT(*) >= 0 AS ok FROM pg_aios;") at postgres.c:1274 But I'm yet to construct a more reliable reproducer for it. Hope I could do this during the current week. Best regards, Alexander Lakhin Neon (https://neon.tech) --------------U1NcQLS9BGVZnYGPQRcTfHTR Content-Type: text/html; charset=UTF-8 Content-Transfer-Encoding: 8bit
Hello Andres,

07.04.2025 19:20, Andres Freund wrote:
iteration 8: Sun Apr  6 19:22:39 UTC 2025
installchecks finished: Sun Apr  6 19:23:47 UTC 2025
2025-04-06 19:22:44.216 UTC [349525] LOG:  could not read blocks 0..0 in file "base/6179194/2606": Operation canceled
2025-04-06 19:22:44.216 UTC [349525] ERROR:  could not read blocks 0..0 in file "base/6179194/2606": Operation canceled

Thanks for the report, clearly something isn't right.

Thank you for your attention to it! 
It's reproduced better on tmpfs for me; probably you would need to increase
NUM_INSTALLCHECKS/NUM_ITERATIONS for your machine.

I ran it for a while in a VM, it hasn't triggered yet. Neither on xfs nor on
tmpfs.

Before sharing the script I tested it on two my machines, but I had
anticipated that the error can be hard to reproduce. Will try to reduce
the reproducer...


      

        
server.log contains:
2025-04-06 19:22:44.215 UTC [38231] LOG:  checkpoint complete: wrote ...
2025-04-06 19:22:44.216 UTC [38231] LOG:  checkpoint starting: immediate force wait flush-all
2025-04-06 19:22:44.216 UTC [349525] LOG:  could not read blocks 0..0 in file "base/6179194/2606": Operation canceled
2025-04-06 19:22:44.216 UTC [349525] STATEMENT:  alter table parted_copytest
attach partition parted_copytest_a1 for values in(1);
2025-04-06 19:22:44.216 UTC [349525] ERROR:  could not read blocks 0..0 in file "base/6179194/2606": Operation canceled
2025-04-06 19:22:44.216 UTC [349525] STATEMENT:  alter table parted_copytest
attach partition parted_copytest_a1 for values in(1);


      

      
Hm. Does the failure vary between occurrences?
- is it always the same statement? Probably not?
- is it always 2606 (i.e. pg_constraint)?
- does the failure always happen around a checkpoint? If so, is it always
  immediate?
- I do assume it's always ECANCELED?


    

    

    I've got three such failures with three runs of of the script to

    answer your questions:

    ...

    iteration 6: Mon Apr  7 18:08:35 UTC 2025

    installchecks finished: Mon Apr  7 18:09:45 UTC 2025

    2025-04-07 18:08:45.369 UTC [1941260] LOG:  could not read blocks
    7..7 in file "base/4448730/1255": Operation canceled

    2025-04-07 18:08:45.369 UTC [1941260] ERROR:  could not read blocks
    7..7 in file "base/4448730/1255": Operation canceled

    server.log:

    ...

    2025-04-07 18:08:44.120 UTC [1713945] LOG:  checkpoint starting: wal

    

    2025-04-07 18:08:45.369 UTC [1941260] LOG:  could not read blocks
    7..7 in file "base/4448730/1255": Operation canceled

    2025-04-07 18:08:45.369 UTC [1941260] STATEMENT:  SELECT
    routine_name, ordinal_position, parameter_name, parameter_default

            FROM information_schema.parameters JOIN
    information_schema.routines USING (specific_schema, specific_name)

            WHERE routine_schema = 'temp_func_test' AND routine_name ~
    '^functest_is_'

            ORDER BY 1, 2;

    2025-04-07 18:08:45.369 UTC [1941260] ERROR:  could not read blocks
    7..7 in file "base/4448730/1255": Operation canceled

    2025-04-07 18:08:45.369 UTC [1941260] STATEMENT:  SELECT
    routine_name, ordinal_position, parameter_name, parameter_default

            FROM information_schema.parameters JOIN
    information_schema.routines USING (specific_schema, specific_name)

            WHERE routine_schema = 'temp_func_test' AND routine_name ~
    '^functest_is_'

            ORDER BY 1, 2;

    ...

    2025-04-07 18:08:51.836 UTC [1713945] LOG:  checkpoint complete:
    wrote 1558 buffers (9.5%), wrote 22 SLRU buffers; 0 WAL file(s)
    added, 0 removed, 33 recycled; write=7.544 s, sync=0.019 s,
    total=7.720 s; sync files=0, longest=0.000 s, average=0.000 s;
    distance=533837 kB, estimate=533837 kB; lsn=C/E532D478, redo
    lsn=C/C7054358

    ...

    

    ---

    iteration 8: Mon Apr  7 18:26:47 UTC 2025

    installchecks finished: Mon Apr  7 18:27:59 UTC 2025

    2025-04-07 18:26:53.252 UTC [2359398] LOG:  could not read blocks
    0..12 in file "base/4/1255": Operation canceled

    2025-04-07 18:26:53.255 UTC [2359398] ERROR:  could not read blocks
    0..12 in file "base/4/1255": Operation canceled

    server.log:

    ...

    2025-04-07 18:26:53.249 UTC [2048053] LOG:  checkpoint complete:
    wrote 3061 buffers (18.7%), wrote 3 SLRU buffers; 0 WAL file(s)
    added, 2 removed, 0 recycled; write=0.051 s, sync=0.002 s,
    total=0.068 s; sync files=0, longest=0.000 s, average=0.000 s;
    distance=18937 kB, estimate=120161 kB; lsn=11/6D42ED30, redo
    lsn=11/6C17AC30

    2025-04-07 18:26:53.251 UTC [2359308] WARNING:  "most_common_elems"
    must be specified when "most_common_elem_freqs" is specified

    2025-04-07 18:26:53.251 UTC [2359351] WARNING: 
    "elem_count_histogram" array cannot contain NULL values

    2025-04-07 18:26:53.252 UTC [2359375] ERROR:  cannot modify
    statistics for relation "testseq"

    2025-04-07 18:26:53.252 UTC [2359375] DETAIL:  This operation is not
    supported for sequences. 

    2025-04-07 18:26:53.252 UTC [2359375] STATEMENT:  SELECT
    pg_catalog.pg_restore_relation_stats(

                'schemaname', 'stats_import',

                'relname', 'testseq');

    2025-04-07 18:26:53.252 UTC [2359375] ERROR:  cannot modify
    statistics for relation "testseq" 

    2025-04-07 18:26:53.252 UTC [2359375] DETAIL:  This operation is not
    supported for sequences.

    2025-04-07 18:26:53.252 UTC [2359375] STATEMENT:  SELECT
    pg_catalog.pg_clear_relation_stats(schemaname => 'stats_import',
    relname => 'testseq');

    2025-04-07 18:26:53.252 UTC [2359398] LOG:  could not read blocks
    0..12 in file "base/4/1255": Operation canceled

    2025-04-07 18:26:53.252 UTC [2359398] STATEMENT:  CREATE DATABASE
    regress020_tbd

            ENCODING utf8 LC_COLLATE "C" LC_CTYPE "C" TEMPLATE
    template0;

    2025-04-07 18:26:53.255 UTC [2359449] ERROR:  invalid input syntax
    for type pg_snapshot: "31:12:" at character 8

    2025-04-07 18:26:53.255 UTC [2359449] STATEMENT:  select
    '31:12:'::pg_snapshot;

    2025-04-07 18:26:53.255 UTC [2359449] ERROR:  invalid input syntax
    for type pg_snapshot: "0:1:" at character 8

    2025-04-07 18:26:53.255 UTC [2359449] STATEMENT:  select
    '0:1:'::pg_snapshot;

    2025-04-07 18:26:53.255 UTC [2359449] ERROR:  invalid input syntax
    for type pg_snapshot: "12:13:0" at character 8

    2025-04-07 18:26:53.255 UTC [2359449] STATEMENT:  select
    '12:13:0'::pg_snapshot;

    2025-04-07 18:26:53.255 UTC [2359449] ERROR:  invalid input syntax
    for type pg_snapshot: "12:16:14,13" at character 8

    2025-04-07 18:26:53.255 UTC [2359449] STATEMENT:  select
    '12:16:14,13'::pg_snapshot;

    2025-04-07 18:26:53.255 UTC [2359398] ERROR:  could not read blocks
    0..12 in file "base/4/1255": Operation canceled

    2025-04-07 18:26:53.255 UTC [2359398] STATEMENT:  CREATE DATABASE
    regress020_tbd

            ENCODING utf8 LC_COLLATE "C" LC_CTYPE "C" TEMPLATE
    template0;

    ...

    ---

    iteration 2: Mon Apr  7 19:02:57 UTC 2025

    installchecks finished: Mon Apr  7 19:04:07 UTC 2025

    2025-04-07 19:03:02.133 UTC [3537488] LOG:  could not read blocks
    0..0 in file "base/902183/2607": Operation canceled

    2025-04-07 19:03:02.133 UTC [3537488] ERROR:  could not read blocks
    0..0 in file "base/902183/2607": Operation canceled

    server.log:

    2025-04-07 19:03:02.129 UTC [3487651] LOG:  checkpoint complete:
    wrote 337 buffers (2.1%), wrote 2 SLRU buffers; 0 WAL file(s) added,
    0 removed, 0 recycled; write=0.013 s, sync=0.001 s, total=0.024 s;
    sync files=0, longest=0.000 s, average=0.000 s; distance=2555 kB,
    estimate=293963 kB; lsn=2/9D3DECE8, redo lsn=2/9D2AAC00

    2025-04-07 19:03:02.129 UTC [3537184] ERROR:  invalid regular
    expression: invalid backreference number

    2025-04-07 19:03:02.129 UTC [3537184] STATEMENT:  select 'xyz' ~
    'x(\w)(?=(\1))'; 

    2025-04-07 19:03:02.129 UTC [3537184] ERROR:  invalid regular
    expression: invalid escape \ sequence

    2025-04-07 19:03:02.129 UTC [3537184] STATEMENT:  select 'a' ~
    '\x7fffffff'; 

    2025-04-07 19:03:02.130 UTC [3537651] ERROR:  operator does not
    exist: point = box at character 23

    2025-04-07 19:03:02.130 UTC [3537651] HINT:  No operator matches the
    given name and argument types. You might need to add explicit type
    casts.

    2025-04-07 19:03:02.130 UTC [3537651] STATEMENT:  select
    '(0,0)'::point in ('(0,0,0,0)'::box, point(0,0));

    2025-04-07 19:03:02.133 UTC [3537362] ERROR:  invalid regular
    expression: invalid backreference number

    2025-04-07 19:03:02.133 UTC [3537362] STATEMENT:  select 'xyz' ~
    'x(\w)(?=\1)'; 

    2025-04-07 19:03:02.133 UTC [3537362] ERROR:  invalid regular
    expression: invalid backreference number

    2025-04-07 19:03:02.133 UTC [3537362] STATEMENT:  select 'xyz' ~
    'x(\w)(?=(\1))';

    2025-04-07 19:03:02.133 UTC [3537362] ERROR:  invalid regular
    expression: invalid escape \ sequence

    2025-04-07 19:03:02.133 UTC [3537362] STATEMENT:  select 'a' ~
    '\x7fffffff';

    2025-04-07 19:03:02.133 UTC [3537488] LOG:  could not read blocks
    0..0 in file "base/902183/2607": Operation canceled

    2025-04-07 19:03:02.133 UTC [3537488] STATEMENT:  SELECT p1.oid,
    p1.proname

        FROM pg_proc as p1

        WHERE 'cstring'::regtype = ANY (p1.proargtypes)

            AND NOT EXISTS(SELECT 1 FROM pg_type WHERE typinput =
    p1.oid)

            AND NOT EXISTS(SELECT 1 FROM pg_conversion WHERE conproc =
    p1.oid)

            AND p1.oid != 'shell_in(cstring)'::regprocedure

        ORDER BY 1;

    2025-04-07 19:03:02.133 UTC [3537488] ERROR:  could not read blocks
    0..0 in file "base/902183/2607": Operation canceled

    2025-04-07 19:03:02.133 UTC [3537488] STATEMENT:  SELECT p1.oid,
    p1.proname

        FROM pg_proc as p1

        WHERE 'cstring'::regtype = ANY (p1.proargtypes)

            AND NOT EXISTS(SELECT 1 FROM pg_type WHERE typinput =
    p1.oid) 

            AND NOT EXISTS(SELECT 1 FROM pg_conversion WHERE conproc =
    p1.oid)

            AND p1.oid != 'shell_in(cstring)'::regprocedure

        ORDER BY 1;

    2025-04-07 19:03:02.135 UTC [3537671] WARNING:  TIME(7) WITH TIME
    ZONE precision reduced to maximum allowed, 6

    2025-04-07 19:03:02.135 UTC [3537671] WARNING:  TIMESTAMP(7) WITH
    TIME ZONE precision reduced to maximum allowed, 6

    2025-04-07 19:03:02.135 UTC [3537671] WARNING:  TIME(7) precision
    reduced to maximum allowed, 6

    2025-04-07 19:03:02.136 UTC [3487651] LOG:  checkpoint starting:
    immediate force wait

    ...

    So I suspect checkpointer, but I'm not sure yet.

    

    (Sometimes (2 out of 5 runs) 10 iterations pass without the error.)

    

    That script  with s/grep 'could not read blocks '/grep 'was
    terminated '/

    also discovers another anomaly (right now on the third run, with 10

    iterations of 30 installchecks):

    Core was generated by `postgres: postgres regress005 [local]
    SELECT                  '.

    Program terminated with signal SIGSEGV, Segmentation fault.

    #0  0x0000000000000000 in ?? ()

    (gdb) bt

    #0  0x0000000000000000 in ?? ()

    #1  0x0000591086d5ccfa in pgaio_io_get_target_description
    (ioh=ioh@entry=0x7ffcf961bc20) at aio_target.c:85

    #2  0x0000591086d5bfdd in pg_get_aios (fcinfo=<optimized out>)
    at aio_funcs.c:218

    #3  0x0000591086bb64c1 in ExecMakeTableFunctionResult
    (setexpr=0x5910bddcbf48, econtext=0x5910bddcbde8,
    argContext=<optimized out>,

        expectedDesc=0x5910bddff918, randomAccess=false) at
    execSRF.c:234

    #4  0x0000591086bc9673 in FunctionNext
    (node=node@entry=0x5910bddcbbd8) at nodeFunctionscan.c:94

    #5  0x0000591086bb7093 in ExecScanFetch (recheckMtd=0x591086bc9522
    <FunctionRecheck>, accessMtd=0x591086bc95a2
    <FunctionNext>, epqstate=0x0,

        node=0x5910bddcbbd8) at
    ../../../src/include/executor/execScan.h:126

    #6  ExecScanExtended (projInfo=0x0, qual=0x0, epqstate=0x0,
    recheckMtd=0x591086bc9522 <FunctionRecheck>,
    accessMtd=0x591086bc95a2 <FunctionNext>,

        node=0x5910bddcbbd8) at
    ../../../src/include/executor/execScan.h:170

    #7  ExecScan (node=0x5910bddcbbd8,
    accessMtd=accessMtd@entry=0x591086bc95a2 <FunctionNext>,
    recheckMtd=recheckMtd@entry=0x591086bc9522 <FunctionRecheck>)

        at execScan.c:59

    #8  0x0000591086bc9580 in ExecFunctionScan (pstate=<optimized
    out>) at nodeFunctionscan.c:269

    #9  0x0000591086bb38f3 in ExecProcNodeFirst (node=0x5910bddcbbd8) at
    execProcnode.c:469

    #10 0x0000591086bc0195 in ExecProcNode (node=0x5910bddcbbd8) at
    ../../../src/include/executor/executor.h:341

    #11 0x0000591086bc021b in fetch_input_tuple
    (aggstate=aggstate@entry=0x5910bddcb480) at nodeAgg.c:563

    #12 0x0000591086bc3825 in agg_retrieve_direct
    (aggstate=aggstate@entry=0x5910bddcb480) at nodeAgg.c:2450

    #13 0x0000591086bc3a19 in ExecAgg (pstate=<optimized out>) at
    nodeAgg.c:2265

    #14 0x0000591086bb38f3 in ExecProcNodeFirst (node=0x5910bddcb480) at
    execProcnode.c:469

    #15 0x0000591086baac23 in ExecProcNode
    (node=node@entry=0x5910bddcb480) at
    ../../../src/include/executor/executor.h:341

    #16 0x0000591086baacd0 in ExecutePlan
    (queryDesc=queryDesc@entry=0x5910bdde0e00,
    operation=operation@entry=CMD_SELECT,
    sendTuples=sendTuples@entry=true,

        numberTuples=numberTuples@entry=0,
    direction=direction@entry=ForwardScanDirection,
    dest=dest@entry=0x5910bddf6070) at execMain.c:1783

    #17 0x0000591086bab79d in standard_ExecutorRun
    (queryDesc=0x5910bdde0e00, direction=ForwardScanDirection, count=0)
    at execMain.c:435

    #18 0x0000591086bab7e0 in ExecutorRun
    (queryDesc=queryDesc@entry=0x5910bdde0e00,
    direction=direction@entry=ForwardScanDirection, count=count@entry=0)

        at execMain.c:371

    #19 0x0000591086da9e9f in PortalRunSelect
    (portal=portal@entry=0x5910bdd72f10, forward=forward@entry=true,
    count=0, count@entry=9223372036854775807,

        dest=dest@entry=0x5910bddf6070) at pquery.c:953

    #20 0x0000591086dab83b in PortalRun
    (portal=portal@entry=0x5910bdd72f10,
    count=count@entry=9223372036854775807,
    isTopLevel=isTopLevel@entry=true,

        dest=dest@entry=0x5910bddf6070,
    altdest=altdest@entry=0x5910bddf6070, qc=qc@entry=0x7ffcf961c9f0) at
    pquery.c:797

    #21 0x0000591086da74a4 in exec_simple_query
    (query_string=query_string@entry=0x5910bdcebe60 "SELECT COUNT(*)
    >= 0 AS ok FROM pg_aios;") at postgres.c:1274

    

    But I'm yet to construct a more reliable reproducer for it. Hope I
    could

    do this during the current week.

    

    Best regards,

    Alexander Lakhin

    Neon (https://neon.tech)
  


--------------U1NcQLS9BGVZnYGPQRcTfHTR--