You can subscribe to this list here.
2012 |
Jan
(2) |
Feb
|
Mar
|
Apr
(7) |
May
(27) |
Jun
(15) |
Jul
(11) |
Aug
(3) |
Sep
(1) |
Oct
|
Nov
(5) |
Dec
(1) |
---|---|---|---|---|---|---|---|---|---|---|---|---|
2013 |
Jan
(2) |
Feb
|
Mar
|
Apr
|
May
|
Jun
(2) |
Jul
|
Aug
|
Sep
(10) |
Oct
(19) |
Nov
(34) |
Dec
(6) |
2014 |
Jan
(31) |
Feb
(2) |
Mar
(4) |
Apr
|
May
(3) |
Jun
(6) |
Jul
(10) |
Aug
(2) |
Sep
|
Oct
|
Nov
(9) |
Dec
|
2015 |
Jan
(1) |
Feb
|
Mar
|
Apr
|
May
|
Jun
|
Jul
(2) |
Aug
|
Sep
|
Oct
|
Nov
|
Dec
|
From: Koichi S. <koi...@gm...> - 2015-07-10 04:16:44
|
Yes, this could be a bug. To be honest, affect of TRIGGERs for partitions is not well analyzed yet. Yes, coordinator synchronizes command id with datanodes. Command ID increment in trigger functions may have to be taken care of. Thank you; --- Koichi Suzuki https://www.linkedin.com/in/koichidbms 2015-07-10 0:53 GMT+09:00 Krzysztof Nienartowicz < krz...@gm...>: > I'm moving this thread from general to bugs list. > > I run into the "too many KnownAssignedXids" error on the coordinator slave > now - not sure if it's related with this patch or some other problems that > had been there before the patch was created as this error was supposed to > be fixed long time ago. > > > 2015-07-09 13:30:53.074 CEST,,,5137,,559dc09d.1411,66,,2015-07-09 02:30:21 > CEST,,0,LOG,00000,"recovery restart point at 0/294EF478","last completed > transaction was at log time 2015-07-09 > 13:30:51.700251+02",,,,,,,"CreateRestartPoint, xlog.c:8665","" > 2015-07-09 14:00:52.179 CEST,,,5137,,559dc09d.1411,67,,2015-07-09 02:30:21 > CEST,,0,LOG,00000,"restartpoint starting: time",,,,,,,,"LogCheckpointStart, > xlog.c:7885","" > 2015-07-09 14:01:18.391 CEST,,,5137,,559dc09d.1411,68,,2015-07-09 02:30:21 > CEST,,0,LOG,00000,"restartpoint complete: wrote 262 buffers (0.2%); 0 > transaction log file(s) added, 0 removed, 0 recycled; write=26.151 s, > sync=0.032 s, total=26.212 s; sync files=132, longest=0.001 s, > average=0.000 s",,,,,,,,"LogCheckpointEnd, xlog.c:7957","" > 2015-07-09 14:01:18.391 CEST,,,5137,,559dc09d.1411,69,,2015-07-09 02:30:21 > CEST,,0,LOG,00000,"recovery restart point at 0/298F2638","last completed > transaction was at log time 2015-07-09 > 14:00:26.299532+02",,,,,,,"CreateRestartPoint, xlog.c:8665","" > 2015-07-09 14:15:26.138 CEST,,,5093,,559dc09c.13e5,7,,2015-07-09 02:30:20 > CEST,1/0,0,FATAL,XX000,"too many KnownAssignedXids",,,,,"xlog redo commit: > 2015-07-09 14:15:26.138639+02",,,"KnownAssignedXidsAdd, procarray.c:3347","" > 2015-07-09 14:15:26.143 CEST,,,5083,,559dc09c.13db,2,,2015-07-09 02:30:20 > CEST,,0,LOG,00000,"startup process (PID 5093) exited with exit code > 1",,,,,,,,"LogChildExit, postmaster.c:3133","" > 2015-07-09 14:15:26.143 CEST,,,5083,,559dc09c.13db,3,,2015-07-09 02:30:20 > CEST,,0,LOG,00000,"terminating any other active server > processes",,,,,,,,"HandleChildCrash, postmaster.c:2912","" > 2015-07-09 17:09:17.920 CEST,,,10527,,559e8e9d.291f,1,,2015-07-09 17:09:17 > CEST,,0,LOG,00000,"database system was interrupted while in recovery at log > time 2015-07-09 14:00:20 CEST",,"If this has occurred more than once some > data might be corrupted and you might need to choose an earlier recovery > target.",,,,,,"StartupXLOG, xlog.c:6347","" > 2015-07-09 17:09:17.920 CEST,,,10527,,559e8e9d.291f,2,,2015-07-09 17:09:17 > CEST,,0,LOG,00000,"entering standby mode",,,,,,,,"StartupXLOG, > xlog.c:6417","" > 2015-07-09 17:09:17.932 CEST,,,10527,,559e8e9d.291f,3,,2015-07-09 17:09:17 > CEST,1/0,0,LOG,00000,"consistent recovery state reached at > 0/298F2730",,,,,,,,"CheckRecoveryConsistency, xlog.c:7420","" > 2015-07-09 17:09:17.932 CEST,,,10527,,559e8e9d.291f,4,,2015-07-09 17:09:17 > CEST,1/0,0,LOG,00000,"redo starts at 0/298F2638",,,,,,,,"StartupXLOG, > xlog.c:6881","" > 2015-07-09 17:09:17.933 CEST,,,10517,,559e8e9d.2915,1,,2015-07-09 17:09:17 > CEST,,0,LOG,00000,"database system is ready to accept read only > connections",,,,,,,,"sigusr1_handler, postmaster.c:4533","" > 2015-07-09 17:09:17.936 CEST,,,10527,,559e8e9d.291f,5,,2015-07-09 17:09:17 > CEST,1/0,0,FATAL,XX000,"too many KnownAssignedXids",,,,,"xlog redo commit: > 2015-07-09 14:15:26.138639+02",,,"KnownAssignedXidsAdd, procarray.c:3347","" > 2015-07-09 17:09:17.937 CEST,,,10517,,559e8e9d.2915,2,,2015-07-09 17:09:17 > CEST,,0,LOG,00000,"startup process (PID 10527) exited with exit code > 1",,,,,,,,"LogChildExit, postmaster.c:3133","" > 2015-07-09 17:09:17.937 CEST,,,10517,,559e8e9d.2915,3,,2015-07-09 17:09:17 > CEST,,0,LOG,00000,"terminating any other active server > processes",,,,,,,,"HandleChildCrash, postmaster.c:2912","" > 2015-07-09 17:13:42.741 CEST,,,15899,,559e8fa6.3e1b,1,,2015-07-09 17:13:42 > CEST,,0,LOG,00000,"database system was interrupted while in recovery at log > time 2015-07-09 14:00:20 CEST",,"If this has occurred more than once some > data might be corrupted and you might need to choose an earlier recovery > target.",,,,,,"StartupXLOG, xlog.c:6347","" > 2015-07-09 17:13:42.741 CEST,,,15899,,559e8fa6.3e1b,2,,2015-07-09 17:13:42 > CEST,,0,LOG,00000,"entering standby mode",,,,,,,,"StartupXLOG, > xlog.c:6417","" > 2015-07-09 17:13:43.010 CEST,,,15899,,559e8fa6.3e1b,3,,2015-07-09 17:13:42 > CEST,,0,LOG,00000,"restored log file ""00000001000000000000000A"" from > archive",,,,,,,,"RestoreArchivedFile, xlog.c:3277","" > 2015-07-09 17:13:43.040 CEST,,,15899,,559e8fa6.3e1b,4,,2015-07-09 17:13:42 > CEST,1/0,0,LOG,00000,"consistent recovery state reached at > 0/298F2730",,,,,,,,"CheckRecoveryConsistency, xlog.c:7420","" > 2015-07-09 17:13:43.040 CEST,,,15899,,559e8fa6.3e1b,5,,2015-07-09 17:13:42 > CEST,1/0,0,LOG,00000,"redo starts at 0/298F2638",,,,,,,,"StartupXLOG, > xlog.c:6881","" > 2015-07-09 17:13:43.042 CEST,,,15889,,559e8fa6.3e11,1,,2015-07-09 17:13:42 > CEST,,0,LOG,00000,"database system is ready to accept read only > connections",,,,,,,,"sigusr1_handler, postmaster.c:4533","" > 2015-07-09 17:13:43.044 CEST,,,15899,,559e8fa6.3e1b,6,,2015-07-09 17:13:42 > CEST,1/0,0,FATAL,XX000,"too many KnownAssignedXids",,,,,"xlog redo commit: > 2015-07-09 14:15:26.138639+02",,,"KnownAssignedXidsAdd, procarray.c:3347","" > 2015-07-09 17:13:43.045 CEST,,,15889,,559e8fa6.3e11,2,,2015-07-09 17:13:42 > CEST,,0,LOG,00000,"startup process (PID 15899) exited with exit code > 1",,,,,,,,"LogChildExit, postmaster.c:3133","" > 2015-07-09 17:13:43.045 CEST,,,15889,,559e8fa6.3e11,3,,2015-07-09 17:13:42 > CEST,,0,LOG,00000,"terminating any other active server > processes",,,,,,,,"HandleChildCrash, postmaster.c:2912","" > > On Thu, Jul 9, 2015 at 1:09 PM, Krzysztof Nienartowicz < > krz...@un...> wrote: > >> I found the solution: >> I realized partitioning [insert] triggers increment command id with each >> trigger invocation while the transaction is in the COPY block. This seems >> to confuse coordinator to datanode communication as command id messages got >> interleaved with COPY messages and whacks the COPY state machine. >> In XL there's additional call to propagate new command id that does not >> exist in X2, that snapmgr.c:*UpdateActiveSnapshotCommandId *switches on >> sending back new command ids to other nodes. >> >> Switching this off fixes the problem. >> >> Question: Is this command ID propagation really needed except for >> serializable transactions? Any other logic is affected? Is there a cleaner >> solution? >> >> Cheers, >> Krzysztof >> >> /* >> >> * UpdateActiveSnapshotCommandId >> >> * >> >> * Update the current CID of the active snapshot. This can only be >> applied >> >> * to a snapshot that is not referenced elsewhere. >> >> */ >> >> *void* >> >> *UpdateActiveSnapshotCommandId*(*void*) >> >> { >> >> Assert(ActiveSnapshot != NULL); >> >> Assert(ActiveSnapshot->as_snap->active_count == 1); >> >> Assert(ActiveSnapshot->as_snap->regd_count == 0); >> >> >> ActiveSnapshot->as_snap->curcid = GetCurrentCommandId(false); >> >> *#ifdef* XCP >> >> /* >> >> * Set flag so that updated command ID is sent to the datanodes before >> the >> >> * next query. This ensures that the effects of previous statements are >> >> * visible to the subsequent statements >> >> */ >> >> SetSendCommandId(true); //<--------------------- should be false to fix >> the COPY protocol bug. >> >> *#endif* >> >> } >> >> On Thu, Jul 2, 2015 at 4:12 PM, Krzysztof Nienartowicz < >> krz...@un...> wrote: >> >>> Hello, >>> While trying to ingest into the partitioned table via trigger [we >>> patched XL head source to be able to have insert triggers] we got error >>> after [sometimes varying] number of lines ingested, i.e.: >>> <sql> >>> -- simplified example with 3 datanodes, 3 coords, same coord used >>> >>> create or replace function x_t() returns trigger >>> as >>> $BODY$ >>> >>> declare >>> begin >>> IF ( NEW.id between 0 and 10) THEN >>> INSERT INTO x1 VALUES (NEW.*); >>> elsif(NEW.id between 11 and 100) then >>> INSERT INTO x2 VALUES (NEW.*); >>> else >>> INSERT INTO x3 VALUES (NEW.*); >>> end if; >>> return null; >>> end >>> $BODY$ language plpgsql; >>> >>> >>> create table x (id int primary key, ii text) distribute by hash(id); >>> create table x1(check (id between 0 and 10)) inherits (x); >>> create table x2(check (id between 11 and 100)) inherits (x); >>> create table x3(check (id > 100)) inherits (x); >>> >>> CREATE TRIGGER x_t BEFORE INSERT ON x FOR EACH ROW EXECUTE PROCEDURE >>> x_t(); >>> >>> -- populate tables via trigger with insert >>> >>> insert into x select i,rpad('X',300,'y') from generate_series(1,1000) i; >>> explain analyze select count(*) from x; >>> -- all good: >>> -- >>> QUERY >>> PLAN >>> >>> -- >>> -------------------------------------------------------------------------------------------------------------------------------------------------------------- >>> -- Aggregate (cost=559.68..559.69 rows=1 width=0) (actual >>> time=8.808..8.809 rows=1 loops=1) >>> -- -> Append (cost=100.00..541.15 rows=7411 width=0) (actual >>> time=0.677..7.015 rows=1000 loops=1) >>> -- -> Remote Subquery Scan on all >>> (datanode1,datanode2,datanode3) (cost=100.00..100.00 rows=1 width=0) >>> (actual time=0.486..0.486 rows=0 loops=1) >>> -- -> Remote Subquery Scan on all >>> (datanode1,datanode2,datanode3) (cost=100.00..147.05 rows=2470 width=0) >>> (actual time=0.185..0.210 rows=10 loops=1) >>> -- -> Remote Subquery Scan on all >>> (datanode1,datanode2,datanode3) (cost=100.00..147.05 rows=2470 width=0) >>> (actual time=0.246..0.429 rows=90 loops=1) >>> -- -> Remote Subquery Scan on all >>> (datanode1,datanode2,datanode3) (cost=100.00..147.05 rows=2470 width=0) >>> (actual time=0.269..2.507 rows=900 loops=1) >>> >>> >>> </sql> >>> <bash> >>> # do dump >>> psql -p 20004 -h coord1 -c "COPY (select * from x) TO STDOUT DELIMITER >>> AS ';'" | tee /tmp/x.dat | wc -l >>> >>> # all good, 1000 rows saved. >>> # now, truncate and try to reingest: >>> </bash> >>> <sql> >>> truncate table x; >>> </sql> >>> >>> <bash> >>> awk 'NR>0 && NR <= 1000 {print $0;}' /tmp/x.dat | psql -h 20004 -c "set >>> client_min_messages=DEBUG5; COPY dpac_or5_s2_epsl_dex.x FROM STDIN >>> DELIMITER AS ';'" >>> DEBUG: ProcessUtility >>> DEBUG: global snapshot info: gxmin: 63682, gxmax: 63682, gxcnt: 0 >>> DEBUG: conn_count = 3, need_tran_block = true >>> LOG: Connection error invalid string in message >>> LOG: Connection error invalid string in message >>> LOG: Connection error invalid string in message >>> ERROR: Copy failed on a data node >>> CONTEXT: COPY x, line 142: >>> "251;Xyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyy..." >>> DEBUG: Record transaction abort 63682 >>> >>> # repeat the cmd, fails on different line number >>> ERROR: Copy failed on a data node >>> CONTEXT: COPY x, line 241: >>> "655;Xyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyy..." >>> >>> #repeat the cmd, fails on the same line number >>> ERROR: Copy failed on a data node >>> CONTEXT: COPY x, line 142: >>> "251;Xyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyy..." >>> >>> #repeat the cmd, fails on the same line number >>> ERROR: Copy failed on a data node >>> CONTEXT: COPY x, line 142: >>> "251;Xyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyy..." >>> >>> # but when to limit number of rows it would work: >>> >>> awk 'NR>0 && NR <= 100 {print $0;}' /tmp/x.dat | psql -p20004 -c "set >>> client_min_messages=DEBUG5; COPY dpac_or5_s2_epsl_dex.x FROM STDIN >>> DELIMITER AS ';'" >>> DEBUG: ProcessUtility >>> DEBUG: global snapshot info: gxmin: 63723, gxmax: 63723, gxcnt: 0 >>> DEBUG: conn_count = 3, need_tran_block = true >>> DEBUG: CommitTransactionCommand >>> DEBUG: CommitTransaction >>> DEBUG: name: unnamed; blockState: STARTED; state: INPROGR, >>> xid/subid/cid: 63723/1/1 (used), nestlvl: 1, children: >>> DEBUG: Record transaction commit 63723 >>> DEBUG: [re]setting xid = 0, old_value = 0 >>> >>> # select gives back proper number of rows properly distributed by the >>> trigger >>> </bash> >>> >>> Clearly the messages passing rows from coordinator to datanodes are >>> truncated/corrupted somehow (copy.c:622). Of course we could try to make a >>> workaround to copy into the partitions directly, but would really prefer to >>> avoid this. >>> >>> Any hints are welcome how to fix this! >>> >>> Best regards, >>> Krzysztof >>> >>> >>> >> > > > ------------------------------------------------------------------------------ > Don't Limit Your Business. Reach for the Cloud. > GigeNET's Cloud Solutions provide you with the tools and support that > you need to offload your IT needs and focus on growing your business. > Configured For All Businesses. Start Your Cloud Today. > https://www.gigenetcloud.com/ > _______________________________________________ > Postgres-xc-bugs mailing list > Pos...@li... > https://lists.sourceforge.net/lists/listinfo/postgres-xc-bugs > > |
From: Krzysztof N. <krz...@gm...> - 2015-07-09 15:54:03
|
I'm moving this thread from general to bugs list. I run into the "too many KnownAssignedXids" error on the coordinator slave now - not sure if it's related with this patch or some other problems that had been there before the patch was created as this error was supposed to be fixed long time ago. 2015-07-09 13:30:53.074 CEST,,,5137,,559dc09d.1411,66,,2015-07-09 02:30:21 CEST,,0,LOG,00000,"recovery restart point at 0/294EF478","last completed transaction was at log time 2015-07-09 13:30:51.700251+02",,,,,,,"CreateRestartPoint, xlog.c:8665","" 2015-07-09 14:00:52.179 CEST,,,5137,,559dc09d.1411,67,,2015-07-09 02:30:21 CEST,,0,LOG,00000,"restartpoint starting: time",,,,,,,,"LogCheckpointStart, xlog.c:7885","" 2015-07-09 14:01:18.391 CEST,,,5137,,559dc09d.1411,68,,2015-07-09 02:30:21 CEST,,0,LOG,00000,"restartpoint complete: wrote 262 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=26.151 s, sync=0.032 s, total=26.212 s; sync files=132, longest=0.001 s, average=0.000 s",,,,,,,,"LogCheckpointEnd, xlog.c:7957","" 2015-07-09 14:01:18.391 CEST,,,5137,,559dc09d.1411,69,,2015-07-09 02:30:21 CEST,,0,LOG,00000,"recovery restart point at 0/298F2638","last completed transaction was at log time 2015-07-09 14:00:26.299532+02",,,,,,,"CreateRestartPoint, xlog.c:8665","" 2015-07-09 14:15:26.138 CEST,,,5093,,559dc09c.13e5,7,,2015-07-09 02:30:20 CEST,1/0,0,FATAL,XX000,"too many KnownAssignedXids",,,,,"xlog redo commit: 2015-07-09 14:15:26.138639+02",,,"KnownAssignedXidsAdd, procarray.c:3347","" 2015-07-09 14:15:26.143 CEST,,,5083,,559dc09c.13db,2,,2015-07-09 02:30:20 CEST,,0,LOG,00000,"startup process (PID 5093) exited with exit code 1",,,,,,,,"LogChildExit, postmaster.c:3133","" 2015-07-09 14:15:26.143 CEST,,,5083,,559dc09c.13db,3,,2015-07-09 02:30:20 CEST,,0,LOG,00000,"terminating any other active server processes",,,,,,,,"HandleChildCrash, postmaster.c:2912","" 2015-07-09 17:09:17.920 CEST,,,10527,,559e8e9d.291f,1,,2015-07-09 17:09:17 CEST,,0,LOG,00000,"database system was interrupted while in recovery at log time 2015-07-09 14:00:20 CEST",,"If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.",,,,,,"StartupXLOG, xlog.c:6347","" 2015-07-09 17:09:17.920 CEST,,,10527,,559e8e9d.291f,2,,2015-07-09 17:09:17 CEST,,0,LOG,00000,"entering standby mode",,,,,,,,"StartupXLOG, xlog.c:6417","" 2015-07-09 17:09:17.932 CEST,,,10527,,559e8e9d.291f,3,,2015-07-09 17:09:17 CEST,1/0,0,LOG,00000,"consistent recovery state reached at 0/298F2730",,,,,,,,"CheckRecoveryConsistency, xlog.c:7420","" 2015-07-09 17:09:17.932 CEST,,,10527,,559e8e9d.291f,4,,2015-07-09 17:09:17 CEST,1/0,0,LOG,00000,"redo starts at 0/298F2638",,,,,,,,"StartupXLOG, xlog.c:6881","" 2015-07-09 17:09:17.933 CEST,,,10517,,559e8e9d.2915,1,,2015-07-09 17:09:17 CEST,,0,LOG,00000,"database system is ready to accept read only connections",,,,,,,,"sigusr1_handler, postmaster.c:4533","" 2015-07-09 17:09:17.936 CEST,,,10527,,559e8e9d.291f,5,,2015-07-09 17:09:17 CEST,1/0,0,FATAL,XX000,"too many KnownAssignedXids",,,,,"xlog redo commit: 2015-07-09 14:15:26.138639+02",,,"KnownAssignedXidsAdd, procarray.c:3347","" 2015-07-09 17:09:17.937 CEST,,,10517,,559e8e9d.2915,2,,2015-07-09 17:09:17 CEST,,0,LOG,00000,"startup process (PID 10527) exited with exit code 1",,,,,,,,"LogChildExit, postmaster.c:3133","" 2015-07-09 17:09:17.937 CEST,,,10517,,559e8e9d.2915,3,,2015-07-09 17:09:17 CEST,,0,LOG,00000,"terminating any other active server processes",,,,,,,,"HandleChildCrash, postmaster.c:2912","" 2015-07-09 17:13:42.741 CEST,,,15899,,559e8fa6.3e1b,1,,2015-07-09 17:13:42 CEST,,0,LOG,00000,"database system was interrupted while in recovery at log time 2015-07-09 14:00:20 CEST",,"If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.",,,,,,"StartupXLOG, xlog.c:6347","" 2015-07-09 17:13:42.741 CEST,,,15899,,559e8fa6.3e1b,2,,2015-07-09 17:13:42 CEST,,0,LOG,00000,"entering standby mode",,,,,,,,"StartupXLOG, xlog.c:6417","" 2015-07-09 17:13:43.010 CEST,,,15899,,559e8fa6.3e1b,3,,2015-07-09 17:13:42 CEST,,0,LOG,00000,"restored log file ""00000001000000000000000A"" from archive",,,,,,,,"RestoreArchivedFile, xlog.c:3277","" 2015-07-09 17:13:43.040 CEST,,,15899,,559e8fa6.3e1b,4,,2015-07-09 17:13:42 CEST,1/0,0,LOG,00000,"consistent recovery state reached at 0/298F2730",,,,,,,,"CheckRecoveryConsistency, xlog.c:7420","" 2015-07-09 17:13:43.040 CEST,,,15899,,559e8fa6.3e1b,5,,2015-07-09 17:13:42 CEST,1/0,0,LOG,00000,"redo starts at 0/298F2638",,,,,,,,"StartupXLOG, xlog.c:6881","" 2015-07-09 17:13:43.042 CEST,,,15889,,559e8fa6.3e11,1,,2015-07-09 17:13:42 CEST,,0,LOG,00000,"database system is ready to accept read only connections",,,,,,,,"sigusr1_handler, postmaster.c:4533","" 2015-07-09 17:13:43.044 CEST,,,15899,,559e8fa6.3e1b,6,,2015-07-09 17:13:42 CEST,1/0,0,FATAL,XX000,"too many KnownAssignedXids",,,,,"xlog redo commit: 2015-07-09 14:15:26.138639+02",,,"KnownAssignedXidsAdd, procarray.c:3347","" 2015-07-09 17:13:43.045 CEST,,,15889,,559e8fa6.3e11,2,,2015-07-09 17:13:42 CEST,,0,LOG,00000,"startup process (PID 15899) exited with exit code 1",,,,,,,,"LogChildExit, postmaster.c:3133","" 2015-07-09 17:13:43.045 CEST,,,15889,,559e8fa6.3e11,3,,2015-07-09 17:13:42 CEST,,0,LOG,00000,"terminating any other active server processes",,,,,,,,"HandleChildCrash, postmaster.c:2912","" On Thu, Jul 9, 2015 at 1:09 PM, Krzysztof Nienartowicz < krz...@un...> wrote: > I found the solution: > I realized partitioning [insert] triggers increment command id with each > trigger invocation while the transaction is in the COPY block. This seems > to confuse coordinator to datanode communication as command id messages got > interleaved with COPY messages and whacks the COPY state machine. > In XL there's additional call to propagate new command id that does not > exist in X2, that snapmgr.c:*UpdateActiveSnapshotCommandId *switches on > sending back new command ids to other nodes. > > Switching this off fixes the problem. > > Question: Is this command ID propagation really needed except for > serializable transactions? Any other logic is affected? Is there a cleaner > solution? > > Cheers, > Krzysztof > > /* > > * UpdateActiveSnapshotCommandId > > * > > * Update the current CID of the active snapshot. This can only be applied > > * to a snapshot that is not referenced elsewhere. > > */ > > *void* > > *UpdateActiveSnapshotCommandId*(*void*) > > { > > Assert(ActiveSnapshot != NULL); > > Assert(ActiveSnapshot->as_snap->active_count == 1); > > Assert(ActiveSnapshot->as_snap->regd_count == 0); > > > ActiveSnapshot->as_snap->curcid = GetCurrentCommandId(false); > > *#ifdef* XCP > > /* > > * Set flag so that updated command ID is sent to the datanodes before the > > * next query. This ensures that the effects of previous statements are > > * visible to the subsequent statements > > */ > > SetSendCommandId(true); //<--------------------- should be false to fix > the COPY protocol bug. > > *#endif* > > } > > On Thu, Jul 2, 2015 at 4:12 PM, Krzysztof Nienartowicz < > krz...@un...> wrote: > >> Hello, >> While trying to ingest into the partitioned table via trigger [we patched >> XL head source to be able to have insert triggers] we got error after >> [sometimes varying] number of lines ingested, i.e.: >> <sql> >> -- simplified example with 3 datanodes, 3 coords, same coord used >> >> create or replace function x_t() returns trigger >> as >> $BODY$ >> >> declare >> begin >> IF ( NEW.id between 0 and 10) THEN >> INSERT INTO x1 VALUES (NEW.*); >> elsif(NEW.id between 11 and 100) then >> INSERT INTO x2 VALUES (NEW.*); >> else >> INSERT INTO x3 VALUES (NEW.*); >> end if; >> return null; >> end >> $BODY$ language plpgsql; >> >> >> create table x (id int primary key, ii text) distribute by hash(id); >> create table x1(check (id between 0 and 10)) inherits (x); >> create table x2(check (id between 11 and 100)) inherits (x); >> create table x3(check (id > 100)) inherits (x); >> >> CREATE TRIGGER x_t BEFORE INSERT ON x FOR EACH ROW EXECUTE PROCEDURE >> x_t(); >> >> -- populate tables via trigger with insert >> >> insert into x select i,rpad('X',300,'y') from generate_series(1,1000) i; >> explain analyze select count(*) from x; >> -- all good: >> -- >> QUERY >> PLAN >> >> -- >> -------------------------------------------------------------------------------------------------------------------------------------------------------------- >> -- Aggregate (cost=559.68..559.69 rows=1 width=0) (actual >> time=8.808..8.809 rows=1 loops=1) >> -- -> Append (cost=100.00..541.15 rows=7411 width=0) (actual >> time=0.677..7.015 rows=1000 loops=1) >> -- -> Remote Subquery Scan on all >> (datanode1,datanode2,datanode3) (cost=100.00..100.00 rows=1 width=0) >> (actual time=0.486..0.486 rows=0 loops=1) >> -- -> Remote Subquery Scan on all >> (datanode1,datanode2,datanode3) (cost=100.00..147.05 rows=2470 width=0) >> (actual time=0.185..0.210 rows=10 loops=1) >> -- -> Remote Subquery Scan on all >> (datanode1,datanode2,datanode3) (cost=100.00..147.05 rows=2470 width=0) >> (actual time=0.246..0.429 rows=90 loops=1) >> -- -> Remote Subquery Scan on all >> (datanode1,datanode2,datanode3) (cost=100.00..147.05 rows=2470 width=0) >> (actual time=0.269..2.507 rows=900 loops=1) >> >> >> </sql> >> <bash> >> # do dump >> psql -p 20004 -h coord1 -c "COPY (select * from x) TO STDOUT DELIMITER AS >> ';'" | tee /tmp/x.dat | wc -l >> >> # all good, 1000 rows saved. >> # now, truncate and try to reingest: >> </bash> >> <sql> >> truncate table x; >> </sql> >> >> <bash> >> awk 'NR>0 && NR <= 1000 {print $0;}' /tmp/x.dat | psql -h 20004 -c "set >> client_min_messages=DEBUG5; COPY dpac_or5_s2_epsl_dex.x FROM STDIN >> DELIMITER AS ';'" >> DEBUG: ProcessUtility >> DEBUG: global snapshot info: gxmin: 63682, gxmax: 63682, gxcnt: 0 >> DEBUG: conn_count = 3, need_tran_block = true >> LOG: Connection error invalid string in message >> LOG: Connection error invalid string in message >> LOG: Connection error invalid string in message >> ERROR: Copy failed on a data node >> CONTEXT: COPY x, line 142: >> "251;Xyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyy..." >> DEBUG: Record transaction abort 63682 >> >> # repeat the cmd, fails on different line number >> ERROR: Copy failed on a data node >> CONTEXT: COPY x, line 241: >> "655;Xyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyy..." >> >> #repeat the cmd, fails on the same line number >> ERROR: Copy failed on a data node >> CONTEXT: COPY x, line 142: >> "251;Xyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyy..." >> >> #repeat the cmd, fails on the same line number >> ERROR: Copy failed on a data node >> CONTEXT: COPY x, line 142: >> "251;Xyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyy..." >> >> # but when to limit number of rows it would work: >> >> awk 'NR>0 && NR <= 100 {print $0;}' /tmp/x.dat | psql -p20004 -c "set >> client_min_messages=DEBUG5; COPY dpac_or5_s2_epsl_dex.x FROM STDIN >> DELIMITER AS ';'" >> DEBUG: ProcessUtility >> DEBUG: global snapshot info: gxmin: 63723, gxmax: 63723, gxcnt: 0 >> DEBUG: conn_count = 3, need_tran_block = true >> DEBUG: CommitTransactionCommand >> DEBUG: CommitTransaction >> DEBUG: name: unnamed; blockState: STARTED; state: INPROGR, >> xid/subid/cid: 63723/1/1 (used), nestlvl: 1, children: >> DEBUG: Record transaction commit 63723 >> DEBUG: [re]setting xid = 0, old_value = 0 >> >> # select gives back proper number of rows properly distributed by the >> trigger >> </bash> >> >> Clearly the messages passing rows from coordinator to datanodes are >> truncated/corrupted somehow (copy.c:622). Of course we could try to make a >> workaround to copy into the partitions directly, but would really prefer to >> avoid this. >> >> Any hints are welcome how to fix this! >> >> Best regards, >> Krzysztof >> >> >> > |
From: <xu...@cm...> - 2015-01-27 11:29:58
|
Hi In coordinator restore mode. I get coredump when client issue DDL Recreate steps: 1.pg_ctl start -Z restoremode -D /rdbdata/bcrdb_data/coord 2.psql -hzhcx5i -p20015 cxdb 3.create table: CREATE TABLE cm_busi_handle_201301 ( so_nbr bigint, region_code integer, process_id integer, process_result integer, handle_seq integer, op_id integer, oper_date timestamp without time zone, oper_end_date timestamp without time zone, invoice_no character varying(20), property character varying(20), oper_desc text ) DISTRIBUTE BY MODULO (region_code) TO NODE (datanode1,datanode2,datanode3,datanode4,datanode5,datanode6,datanode7,datanode8) 4.get coredump cxdb=# CREATE TABLE cm_busi_handle_201301 ( cxdb(# so_nbr bigint, cxdb(# region_code integer, cxdb(# process_id integer, cxdb(# process_result integer, cxdb(# handle_seq integer, cxdb(# op_id integer, cxdb(# oper_date timestamp without time zone, cxdb(# oper_end_date timestamp without time zone, cxdb(# invoice_no character varying(20), cxdb(# property character varying(20), cxdb(# oper_desc text cxdb(# ) cxdb-# DISTRIBUTE BY MODULO (region_code) cxdb-# TO NODE (datanode1,datanode2,datanode3,datanode4,datanode5,datanode6,datanode7,datanode8); The connection to the server was lost. Attempting reset: Failed. !> 5.stack when get coredump gdb /rdbdata/bcrdb_install/bin/postgres /tmp/corefile/core.postgres.48524 (gd bt #0 0x00000036a48328a5 in raise () from /lib64/libc.so.6 #1 0x00000036a4834085 in abort () from /lib64/libc.so.6 #2 0x00000036a486fa37 in __libc_message () from /lib64/libc.so.6 #3 0x00000036a4875366 in malloc_printerr () from /lib64/libc.so.6 #4 0x00000036a4877e93 in _int_free () from /lib64/libc.so.6 #5 0x0000000000769879 in AllocSetDelete (context=<value optimized out>) at aset.c:551 #6 0x0000000000769dad in MemoryContextDelete (context=0x12231e8) at mcxt.c:193 #7 0x000000000076aa70 in PortalDrop (portal=0x122d0c0, isTopCommit=<value optimized out>) at portalmem.c:588 #8 0x000000000067ddaa in exec_simple_query ( query_string=0x114c1e0 "CREATE TABLE cm_busi_handle_201301 (\n so_nbr bigint,\n region_code integer,\n process_id integer,\n process_result integer,\n handle_seq integer,\n op_id integer,\n oper_date timestamp "...) at postgres.c:1149 #9 0x000000000067f82f in PostgresMain (argc=<value optimized out>, argv=<value optimized out>, dbname=0x1166708 "cxdb", username=<value optimized out>) at postgres.c:4243 #10 0x000000000063b84a in BackendRun (argc=<value optimized out>, argv=<value optimized out>) at postmaster.c:4202 #11 BackendStartup (argc=<value optimized out>, argv=<value optimized out>) at postmaster.c:3891 #12 ServerLoop (argc=<value optimized out>, argv=<value optimized out>) at postmaster.c:1702 #13 PostmasterMain (argc=<value optimized out>, argv=<value optimized out>) at postmaster.c:1369 #14 0x00000000005d1420 in main (argc=4, argv=0x1131c70) at main.c:206 My analysis is as below: when I start coordinator in restoremode. Pooler process is not running. So NumDataNodes is zero. so there is a problem in function BuildRelationDistributionNodes { //In restoremode. NumDataNodes is 0. So memory allocation has the problem. when the parameter of palloc0 is 0.Then palloc0 allocate smallest chunk to //nodeoids. If we need more memory, there is a memory overflow. so when postgres free memory, get coredump nodeoids = (Oid ) palloc0(NumDataNodes * sizeof(Oid)); } The right code as follows: BuildRelationDistributionNodes(List *nodes, int *numnodes) { Oid *nodeoids; ListCell *item; *numnodes = 0; int numdatanotes; numdatanotes=list_length(nodes); nodeoids = (Oid *) palloc0(numdatanotes*sizeof(Oid)); } In my team, Test result is ok. Please review these code, If any problem. Please let me know. xu...@cm... |
From: Zhou L. <zh...@gm...> - 2014-11-24 09:33:31
|
In second scenario, the reason is that coordinator sends unregister command twice to gtm proxy : UnregisterGTM(GTM_PGXCNodeType type) { int ret; CheckConnection(); if (!conn) return EOF; ret = node_unregister(conn, type, PGXCNodeName); /* If something went wrong, retry once */ if (ret < 0) { CloseGTM(); InitGTM(); if (conn) ret = node_unregister(conn, type, PGXCNodeName); } ... } Gtm proxy Recovery_PGXCNodeUnregister return success for the first unregister command,but gtm return failure because of gtm restarting, then coordinator send the second unregister command , so the Recovery_PGXCNodeUnregister will fail , siglongjmp happens. Patch attached to fix. It maybe not the best fix approach, please advice. 2014-11-17 17:54 GMT+08:00 Zhou Liang <zh...@gm...>: > I found gtm proxy have some problems after gtm restarting , my environment > is rhel7 and pgxc1.2. > > 1、gtm_proxy don't handle SIGPIPE , so gtm_proxy also down when gtm down, > it sometimes occur. > reproduce steps: > PGXC stop gtm master > Stop GTM master > waiting for server to shut down.... done > server stopped > PGXC > PGXC monitor all > Not running: gtm master > Running: gtm proxy gtm_pxy1 > Running: gtm proxy gtm_pxy2 > Running: coordinator master coord1 > Running: coordinator master coord2 > Running: datanode master datanode1 > Running: datanode master datanode2 > PGXC > PGXC monitor all > Not running: gtm master > Not running: gtm proxy gtm_pxy1 > Not running: gtm proxy gtm_pxy2 > Running: coordinator master coord1 > Running: coordinator master coord2 > Running: datanode master datanode1 > Running: datanode master datanode2 > ----------------------------------------------------- > Program received signal SIGPIPE, Broken pipe. > 0x00007ff3cf3aa75b in send () from /lib64/libpthread.so.0 > (gdb) bt > #0 0x00007ff3cf3aa75b in send () from /lib64/libpthread.so.0 > #1 0x0000000000403c31 in gtmpqSendSome (conn=0x7ff3c80028f0, len=21) at > fe-misc.c:753 > #2 0x0000000000403daf in gtmpqFlush (conn=0x7ff3c80028f0) at fe-misc.c:848 > #3 0x000000000042331c in GTMProxy_ThreadMain (argp=0x1ccbb60) at > proxy_main.c:1526 > #4 0x00000000004281db in GTMProxy_ThreadMainWrapper (argp=0x1ccbb60) at > proxy_thread.c:319 > #5 0x00007ff3cf3a3df3 in start_thread () from /lib64/libpthread.so.0 > #6 0x00007ff3cf0d13dd in clone () from /lib64/libc.so.6 > > 2、i try to use pqsignal(SIGPIPE, SIG_IGN) to ignore a signal SIGPIPE, but > another question occur, steps: > PGXC stop gtm master > PGXC start gtm master // because of gtm restart , gtm proxy process > coordinaor or datanode unregiste command will fail > PGXC stop coordinator master coord1 // when stop coord1 , coord1 send > unregiste command 'C' , then 'X' to gtm proxy > PGXC start coordinator master coord1 > PGXC Psql postgres > Selected coord1. > psql (PGXC , based on PG 9.3.4) > Type "help" for help. > postgres=# \d > WARNING: Xid is invalid. > WARNING: Xid is invalid. > WARNING: Xid is invalid. > ERROR: GTM error, could not obtain snapshot XID = 0 > -------------------------------------- > static void > ProcessPGXCNodeCommand(GTMProxy_ConnectionInfo *conninfo, GTM_Conn > *gtm_conn, > GTM_MessageType mtype, StringInfo message) > { .... > /* Unregister Node also on Proxy */ > if (Recovery_PGXCNodeUnregister(cmd_data.cd_reg.type, > cmd_data.cd_reg.nodename, > false, > conninfo->con_port->sock)) > { > ereport(ERROR, > (EINVAL, > errmsg("Failed to Unregister node"))); // gtm proxy process > unregiste command 'C', if Recovery_PGXCNodeUnregister fail , ERROR lead to > siglongjmp > } > ... > } > after this siglongjmp, gtm proxy will continue to process old unregister > command 'C', Recovery_PGXCNodeUnregister still fail, then continue to > siglongjmp. this phenomena cycle occurs. so gtm proxy cann't handler other > connections , it blocks coordinator and datanode get xid. > > 3、if unregister proxy fail because of gtm restarting, this siglongjmp > happens,gtm proxy doesn't stop propley. as follows: > /* > * Unregister Proxy on GTM > */ > static void > UnregisterProxy(void) > { ... > failed: > elog(ERROR, "can not Unregister Proxy on GTM"); // ERROR lead to > siglongjmp. > } > > these scenarios is rare , but can anyone fix the problem? > > > > -- > Thanks > Zhou Liang > -- Thanks Zhou Liang |
From: Zhou L. <zh...@gm...> - 2014-11-17 09:54:28
|
I found gtm proxy have some problems after gtm restarting , my environment is rhel7 and pgxc1.2. 1、gtm_proxy don't handle SIGPIPE , so gtm_proxy also down when gtm down, it sometimes occur. reproduce steps: PGXC stop gtm master Stop GTM master waiting for server to shut down.... done server stopped PGXC PGXC monitor all Not running: gtm master Running: gtm proxy gtm_pxy1 Running: gtm proxy gtm_pxy2 Running: coordinator master coord1 Running: coordinator master coord2 Running: datanode master datanode1 Running: datanode master datanode2 PGXC PGXC monitor all Not running: gtm master Not running: gtm proxy gtm_pxy1 Not running: gtm proxy gtm_pxy2 Running: coordinator master coord1 Running: coordinator master coord2 Running: datanode master datanode1 Running: datanode master datanode2 ----------------------------------------------------- Program received signal SIGPIPE, Broken pipe. 0x00007ff3cf3aa75b in send () from /lib64/libpthread.so.0 (gdb) bt #0 0x00007ff3cf3aa75b in send () from /lib64/libpthread.so.0 #1 0x0000000000403c31 in gtmpqSendSome (conn=0x7ff3c80028f0, len=21) at fe-misc.c:753 #2 0x0000000000403daf in gtmpqFlush (conn=0x7ff3c80028f0) at fe-misc.c:848 #3 0x000000000042331c in GTMProxy_ThreadMain (argp=0x1ccbb60) at proxy_main.c:1526 #4 0x00000000004281db in GTMProxy_ThreadMainWrapper (argp=0x1ccbb60) at proxy_thread.c:319 #5 0x00007ff3cf3a3df3 in start_thread () from /lib64/libpthread.so.0 #6 0x00007ff3cf0d13dd in clone () from /lib64/libc.so.6 2、i try to use pqsignal(SIGPIPE, SIG_IGN) to ignore a signal SIGPIPE, but another question occur, steps: PGXC stop gtm master PGXC start gtm master // because of gtm restart , gtm proxy process coordinaor or datanode unregiste command will fail PGXC stop coordinator master coord1 // when stop coord1 , coord1 send unregiste command 'C' , then 'X' to gtm proxy PGXC start coordinator master coord1 PGXC Psql postgres Selected coord1. psql (PGXC , based on PG 9.3.4) Type "help" for help. postgres=# \d WARNING: Xid is invalid. WARNING: Xid is invalid. WARNING: Xid is invalid. ERROR: GTM error, could not obtain snapshot XID = 0 -------------------------------------- static void ProcessPGXCNodeCommand(GTMProxy_ConnectionInfo *conninfo, GTM_Conn *gtm_conn, GTM_MessageType mtype, StringInfo message) { .... /* Unregister Node also on Proxy */ if (Recovery_PGXCNodeUnregister(cmd_data.cd_reg.type, cmd_data.cd_reg.nodename, false, conninfo->con_port->sock)) { ereport(ERROR, (EINVAL, errmsg("Failed to Unregister node"))); // gtm proxy process unregiste command 'C', if Recovery_PGXCNodeUnregister fail , ERROR lead to siglongjmp } ... } after this siglongjmp, gtm proxy will continue to process old unregister command 'C', Recovery_PGXCNodeUnregister still fail, then continue to siglongjmp. this phenomena cycle occurs. so gtm proxy cann't handler other connections , it blocks coordinator and datanode get xid. 3、if unregister proxy fail because of gtm restarting, this siglongjmp happens,gtm proxy doesn't stop propley. as follows: /* * Unregister Proxy on GTM */ static void UnregisterProxy(void) { ... failed: elog(ERROR, "can not Unregister Proxy on GTM"); // ERROR lead to siglongjmp. } these scenarios is rare , but can anyone fix the problem? -- Thanks Zhou Liang |
From: ZhangJulian <jul...@ou...> - 2014-11-17 07:08:36
|
The error has nothing to do with ALTER TABLE DELETE NODE, which is only to make current sessions connecting to other coordinators. The error is about "pgxc_ctl remove datanode master datanode4", anyway, we can work around it by restaring the whole cluster once the cluster status is changed. From: ko...@in... To: jul...@ou... CC: pos...@li... Subject: Re: [Postgres-xc-bugs] Error about pgxc_pool_reload() Date: Mon, 17 Nov 2014 05:44:15 +0000 I’m thinking that pgxc_pool_reload() may not be a good solution. To be honest, ALTER TABLE DELETE NODE has nothing to do with the pooler. It just drops specified node from the node list of pgxc_class. I suspect there may be another cause for the problem. Furthermore, pgxc_pool_reload() enforces to release all the existing pooler connections to all the node, which may affect existing transactions. I’d suggest to be a big careful about this handling. Regards; --- Koichi Suzuki 2014/11/14 18:35、ZhangJulian <jul...@ou...> のメル: Thanks for the quich reply! Furthermore, do you think the pgxc_ctl tool should issue the "select pgxc_pool_reload()" to all the coordinators after it realize the cluster nodes has been changed? Thanks Julian From: ko...@in... To: jul...@ou... CC: pos...@li... Subject: Re: [Postgres-xc-bugs] Error about pgxc_pool_reload() Date: Fri, 14 Nov 2014 09:25:12 +0000 Hmm. pgxc_pool_reload() just reads all the pgxc_node catalog, which is usually very small and I think we can ignore its overhead. Please let me think about the idea. May respond early next week. Thank you very much; --- Koichi Suzuki 2014/11/14 18:10、ZhangJulian <jul...@ou...> のメル: ======Scenario 1: To recreate it, create a 4C4D environment and connect to coord1: create table t1(id int) distribute by hash(id); insert into t1 (select generate_series(1, 1000)); ALTER TABLE t1 DELETE NODE (datanode4); \! pgxc_ctl remove datanode master datanode4 select pgxc_pool_reload(); ==>psql to other coordinators, run select pgxc_pool_reload(); create table t2(id int) distribute by hash(id); ERROR: cache lookup failed for node 16390 ======Scenario 2: To work around it, create table t1(id int) distribute by hash(id); insert into t1 (select generate_series(1, 1000)); ALTER TABLE t1 DELETE NODE (datanode4); ==>psql to other coordinators before "pgxc_ctl remove datanode" \! pgxc_ctl remove datanode master datanode4 select pgxc_pool_reload(); ==>run select pgxc_pool_reload() on the other connected coordinators create table t2(id int) distribute by hash(id); Success!! ======After the debug, In the function, Datum pgxc_pool_reload(PG_FUNCTION_ARGS) { ...... /* No need to reload, node information is consistent */ if (PoolManagerCheckConnectionInfo()) { /* Release the lock on pooler */ PoolManagerLock(false); PG_RETURN_BOOL(true); } ...... /* Signal other sessions to reconnect to pooler */ ReloadConnInfoOnBackends(); ...... } In Scenario 1, the new connected sessions could get the updated cluster stat values, for example, "NumDataNodes". Then PoolManagerCheckConnectionInfo() will return true, and ReloadConnInfoOnBackends has no chance to be executed. That is why Scenario 2 could work around it, since the old sessions know the cluster has been changed and could signal other backends (the backend on coord2-4 for the session of coord1) by ReloadConnInfoOnBackends(). ======The possible fix. Erase the short path of PoolManagerCheckConnectionInfo() check, do the whole process once user run "select pgxc_pool_reload(). Please advise! Thanks Julian ------------------------------------------------------------------------------ Comprehensive Server Monitoring with Site24x7. Monitor 10 servers for $9/Month. Get alerted through email, SMS, voice calls or mobile push notifications. Take corrective actions from your mobile device. http://pubads.g.doubleclick.net/gampad/clk?id=154624111&iu=/4140/ostg.clktrk_______________________________________________ Postgres-xc-bugs mailing list Pos...@li... https://lists.sourceforge.net/lists/listinfo/postgres-xc-bugs |
From: 鈴木 幸市 <ko...@in...> - 2014-11-17 05:44:29
|
I’m thinking that pgxc_pool_reload() may not be a good solution. To be honest, ALTER TABLE DELETE NODE has nothing to do with the pooler. It just drops specified node from the node list of pgxc_class. I suspect there may be another cause for the problem. Furthermore, pgxc_pool_reload() enforces to release all the existing pooler connections to all the node, which may affect existing transactions. I’d suggest to be a big careful about this handling. Regards; --- Koichi Suzuki 2014/11/14 18:35、ZhangJulian <jul...@ou...<mailto:jul...@ou...>> のメール: Thanks for the quich reply! Furthermore, do you think the pgxc_ctl tool should issue the "select pgxc_pool_reload()" to all the coordinators after it realize the cluster nodes has been changed? Thanks Julian ________________________________ From: ko...@in...<mailto:ko...@in...> To: jul...@ou...<mailto:jul...@ou...> CC: pos...@li...<mailto:pos...@li...> Subject: Re: [Postgres-xc-bugs] Error about pgxc_pool_reload() Date: Fri, 14 Nov 2014 09:25:12 +0000 Hmm. pgxc_pool_reload() just reads all the pgxc_node catalog, which is usually very small and I think we can ignore its overhead. Please let me think about the idea. May respond early next week. Thank you very much; --- Koichi Suzuki 2014/11/14 18:10、ZhangJulian <jul...@ou...<mailto:jul...@ou...>> のメール: ======Scenario 1: To recreate it, create a 4C4D environment and connect to coord1: create table t1(id int) distribute by hash(id); insert into t1 (select generate_series(1, 1000)); ALTER TABLE t1 DELETE NODE (datanode4); \! pgxc_ctl remove datanode master datanode4 select pgxc_pool_reload(); ==>psql to other coordinators, run select pgxc_pool_reload(); create table t2(id int) distribute by hash(id); ERROR: cache lookup failed for node 16390 ======Scenario 2: To work around it, create table t1(id int) distribute by hash(id); insert into t1 (select generate_series(1, 1000)); ALTER TABLE t1 DELETE NODE (datanode4); ==>psql to other coordinators before "pgxc_ctl remove datanode" \! pgxc_ctl remove datanode master datanode4 select pgxc_pool_reload(); ==>run select pgxc_pool_reload() on the other connected coordinators create table t2(id int) distribute by hash(id); Success!! ======After the debug, In the function, Datum pgxc_pool_reload(PG_FUNCTION_ARGS) { ...... /* No need to reload, node information is consistent */ if (PoolManagerCheckConnectionInfo()) { /* Release the lock on pooler */ PoolManagerLock(false); PG_RETURN_BOOL(true); } ...... /* Signal other sessions to reconnect to pooler */ ReloadConnInfoOnBackends(); ...... } In Scenario 1, the new connected sessions could get the updated cluster stat values, for example, "NumDataNodes". Then PoolManagerCheckConnectionInfo() will return true, and ReloadConnInfoOnBackends has no chance to be executed. That is why Scenario 2 could work around it, since the old sessions know the cluster has been changed and could signal other backends (the backend on coord2-4 for the session of coord1) by ReloadConnInfoOnBackends(). ======The possible fix. Erase the short path of PoolManagerCheckConnectionInfo() check, do the whole process once user run "select pgxc_pool_reload(). Please advise! Thanks Julian ------------------------------------------------------------------------------ Comprehensive Server Monitoring with Site24x7. Monitor 10 servers for $9/Month. Get alerted through email, SMS, voice calls or mobile push notifications. Take corrective actions from your mobile device. http://pubads.g.doubleclick.net/gampad/clk?id=154624111&iu=/4140/ostg.clktrk_______________________________________________ Postgres-xc-bugs mailing list Pos...@li...<mailto:Pos...@li...> https://lists.sourceforge.net/lists/listinfo/postgres-xc-bugs |
From: ZhangJulian <jul...@ou...> - 2014-11-14 09:35:09
|
Thanks for the quich reply! Furthermore, do you think the pgxc_ctl tool should issue the "select pgxc_pool_reload()" to all the coordinators after it realize the cluster nodes has been changed? Thanks Julian From: ko...@in... To: jul...@ou... CC: pos...@li... Subject: Re: [Postgres-xc-bugs] Error about pgxc_pool_reload() Date: Fri, 14 Nov 2014 09:25:12 +0000 Hmm. pgxc_pool_reload() just reads all the pgxc_node catalog, which is usually very small and I think we can ignore its overhead. Please let me think about the idea. May respond early next week. Thank you very much; --- Koichi Suzuki 2014/11/14 18:10、ZhangJulian <jul...@ou...> のメル: ======Scenario 1: To recreate it, create a 4C4D environment and connect to coord1: create table t1(id int) distribute by hash(id); insert into t1 (select generate_series(1, 1000)); ALTER TABLE t1 DELETE NODE (datanode4); \! pgxc_ctl remove datanode master datanode4 select pgxc_pool_reload(); ==>psql to other coordinators, run select pgxc_pool_reload(); create table t2(id int) distribute by hash(id); ERROR: cache lookup failed for node 16390 ======Scenario 2: To work around it, create table t1(id int) distribute by hash(id); insert into t1 (select generate_series(1, 1000)); ALTER TABLE t1 DELETE NODE (datanode4); ==>psql to other coordinators before "pgxc_ctl remove datanode" \! pgxc_ctl remove datanode master datanode4 select pgxc_pool_reload(); ==>run select pgxc_pool_reload() on the other connected coordinators create table t2(id int) distribute by hash(id); Success!! ======After the debug, In the function, Datum pgxc_pool_reload(PG_FUNCTION_ARGS) { ...... /* No need to reload, node information is consistent */ if (PoolManagerCheckConnectionInfo()) { /* Release the lock on pooler */ PoolManagerLock(false); PG_RETURN_BOOL(true); } ...... /* Signal other sessions to reconnect to pooler */ ReloadConnInfoOnBackends(); ...... } In Scenario 1, the new connected sessions could get the updated cluster stat values, for example, "NumDataNodes". Then PoolManagerCheckConnectionInfo() will return true, and ReloadConnInfoOnBackends has no chance to be executed. That is why Scenario 2 could work around it, since the old sessions know the cluster has been changed and could signal other backends (the backend on coord2-4 for the session of coord1) by ReloadConnInfoOnBackends(). ======The possible fix. Erase the short path of PoolManagerCheckConnectionInfo() check, do the whole process once user run "select pgxc_pool_reload(). Please advise! Thanks Julian ------------------------------------------------------------------------------ Comprehensive Server Monitoring with Site24x7. Monitor 10 servers for $9/Month. Get alerted through email, SMS, voice calls or mobile push notifications. Take corrective actions from your mobile device. http://pubads.g.doubleclick.net/gampad/clk?id=154624111&iu=/4140/ostg.clktrk_______________________________________________ Postgres-xc-bugs mailing list Pos...@li... https://lists.sourceforge.net/lists/listinfo/postgres-xc-bugs |
From: 鈴木 幸市 <ko...@in...> - 2014-11-14 09:26:41
|
Hmm. pgxc_pool_reload() just reads all the pgxc_node catalog, which is usually very small and I think we can ignore its overhead. Please let me think about the idea. May respond early next week. Thank you very much; --- Koichi Suzuki 2014/11/14 18:10、ZhangJulian <jul...@ou...<mailto:jul...@ou...>> のメール: ======Scenario 1: To recreate it, create a 4C4D environment and connect to coord1: create table t1(id int) distribute by hash(id); insert into t1 (select generate_series(1, 1000)); ALTER TABLE t1 DELETE NODE (datanode4); \! pgxc_ctl remove datanode master datanode4 select pgxc_pool_reload(); ==>psql to other coordinators, run select pgxc_pool_reload(); create table t2(id int) distribute by hash(id); ERROR: cache lookup failed for node 16390 ======Scenario 2: To work around it, create table t1(id int) distribute by hash(id); insert into t1 (select generate_series(1, 1000)); ALTER TABLE t1 DELETE NODE (datanode4); ==>psql to other coordinators before "pgxc_ctl remove datanode" \! pgxc_ctl remove datanode master datanode4 select pgxc_pool_reload(); ==>run select pgxc_pool_reload() on the other connected coordinators create table t2(id int) distribute by hash(id); Success!! ======After the debug, In the function, Datum pgxc_pool_reload(PG_FUNCTION_ARGS) { ...... /* No need to reload, node information is consistent */ if (PoolManagerCheckConnectionInfo()) { /* Release the lock on pooler */ PoolManagerLock(false); PG_RETURN_BOOL(true); } ...... /* Signal other sessions to reconnect to pooler */ ReloadConnInfoOnBackends(); ...... } In Scenario 1, the new connected sessions could get the updated cluster stat values, for example, "NumDataNodes". Then PoolManagerCheckConnectionInfo() will return true, and ReloadConnInfoOnBackends has no chance to be executed. That is why Scenario 2 could work around it, since the old sessions know the cluster has been changed and could signal other backends (the backend on coord2-4 for the session of coord1) by ReloadConnInfoOnBackends(). ======The possible fix. Erase the short path of PoolManagerCheckConnectionInfo() check, do the whole process once user run "select pgxc_pool_reload(). Please advise! Thanks Julian ------------------------------------------------------------------------------ Comprehensive Server Monitoring with Site24x7. Monitor 10 servers for $9/Month. Get alerted through email, SMS, voice calls or mobile push notifications. Take corrective actions from your mobile device. http://pubads.g.doubleclick.net/gampad/clk?id=154624111&iu=/4140/ostg.clktrk_______________________________________________ Postgres-xc-bugs mailing list Pos...@li... https://lists.sourceforge.net/lists/listinfo/postgres-xc-bugs |
From: ZhangJulian <jul...@ou...> - 2014-11-14 09:11:03
|
======Scenario 1: To recreate it, create a 4C4D environment and connect to coord1: create table t1(id int) distribute by hash(id); insert into t1 (select generate_series(1, 1000)); ALTER TABLE t1 DELETE NODE (datanode4); \! pgxc_ctl remove datanode master datanode4 select pgxc_pool_reload(); ==>psql to other coordinators, run select pgxc_pool_reload(); create table t2(id int) distribute by hash(id); ERROR: cache lookup failed for node 16390 ======Scenario 2: To work around it, create table t1(id int) distribute by hash(id); insert into t1 (select generate_series(1, 1000)); ALTER TABLE t1 DELETE NODE (datanode4); ==>psql to other coordinators before "pgxc_ctl remove datanode" \! pgxc_ctl remove datanode master datanode4 select pgxc_pool_reload(); ==>run select pgxc_pool_reload() on the other connected coordinators create table t2(id int) distribute by hash(id); Success!! ======After the debug, In the function, Datum pgxc_pool_reload(PG_FUNCTION_ARGS) { ...... /* No need to reload, node information is consistent */ if (PoolManagerCheckConnectionInfo()) { /* Release the lock on pooler */ PoolManagerLock(false); PG_RETURN_BOOL(true); } ...... /* Signal other sessions to reconnect to pooler */ ReloadConnInfoOnBackends(); ...... } In Scenario 1, the new connected sessions could get the updated cluster stat values, for example, "NumDataNodes". Then PoolManagerCheckConnectionInfo() will return true, and ReloadConnInfoOnBackends has no chance to be executed. That is why Scenario 2 could work around it, since the old sessions know the cluster has been changed and could signal other backends (the backend on coord2-4 for the session of coord1) by ReloadConnInfoOnBackends(). ======The possible fix. Erase the short path of PoolManagerCheckConnectionInfo() check, do the whole process once user run "select pgxc_pool_reload(). Please advise! Thanks Julian |
From: 鈴木 幸市 <ko...@in...> - 2014-11-14 07:09:04
|
Ouch! Yes, you’re right. This needs immediate correction. I will submit a patch to correct this and commit it. Thank you very much for pointing out! --- Koichi Suzuki 2014/11/14 16:02、ZhangJulian <jul...@ou...<mailto:jul...@ou...>> のメール: void GTM_WriteRestorePointXid(FILE *f) { if ((MaxGlobalTransactionId - GTMTransactions.gt_nextXid) <= RestoreDuration) GTMTransactions.gt_backedUpXid = GTMTransactions.gt_nextXid + RestoreDuration; else GTMTransactions.gt_backedUpXid = FirstNormalGlobalTransactionId + (RestoreDuration - (MaxGlobalTransactionId - GTMTransactions.gt_nextXid)); elog(LOG, "Saving transaction restoration info, backed-up gxid: %u", GTMTransactions.gt_backedUpXid); fprintf(f, "%u\n", GTMTransactions.gt_backedUpXid); } It seems the operator "<=" in the "if" clause should be ">=", right? ------------------------------------------------------------------------------ Comprehensive Server Monitoring with Site24x7. Monitor 10 servers for $9/Month. Get alerted through email, SMS, voice calls or mobile push notifications. Take corrective actions from your mobile device. http://pubads.g.doubleclick.net/gampad/clk?id=154624111&iu=/4140/ostg.clktrk_______________________________________________ Postgres-xc-bugs mailing list Pos...@li... https://lists.sourceforge.net/lists/listinfo/postgres-xc-bugs |
From: ZhangJulian <jul...@ou...> - 2014-11-14 07:02:25
|
void GTM_WriteRestorePointXid(FILE *f) { if ((MaxGlobalTransactionId - GTMTransactions.gt_nextXid) <= RestoreDuration) GTMTransactions.gt_backedUpXid = GTMTransactions.gt_nextXid + RestoreDuration; else GTMTransactions.gt_backedUpXid = FirstNormalGlobalTransactionId + (RestoreDuration - (MaxGlobalTransactionId - GTMTransactions.gt_nextXid)); elog(LOG, "Saving transaction restoration info, backed-up gxid: %u", GTMTransactions.gt_backedUpXid); fprintf(f, "%u\n", GTMTransactions.gt_backedUpXid); } It seems the operator "<=" in the "if" clause should be ">=", right? |
From: Koichi S. <koi...@gm...> - 2014-08-19 14:49:30
|
Thanks a lot for the report. It is pgxc_ctl bug. Replication should be synchronous. Will submit a fix soon. --- Koichi Suzuki 2014-08-19 23:40 GMT+09:00 zhou liang <zh...@gm...>: > Hi All, > Datanode streaming replication state is async after pgxc_ctl command > init all or start all。Datanode master sync_state is async in > pg_stat_replication,as fallows : > postgres=# select * from pg_stat_replication; > pid | usesysid | usename | application_name | client_addr | > client_hostname | client_port | backend_start | > state | sent_location | write_location | flush_location | > replay_location | sync_priority | sync_state > ------+----------+---------+------------------+----------------+-----------------+-------------+-------------------------------+-----------+---------------+----------------+----------------+-----------------+---------------+------------ > 2772 | 10 | postgres | datanode2 | 192.168.34.162 | > | 51715 | 2014-08-20 04:35:39.561691+08 | streaming > | 0/30011E8 | 0/30011E8 | 0/30011E8 | 0/30011B8 | > 0 | async > (1 row) > postgres=# show synchronous_standby_names; > synchronous_standby_names > --------------------------- > (1 row) > > behavior of pgxc_ctl : > 1、when stoping datanode slave,prepare_stopDatanodeSlave() set the > master to asynchronous mode by changing datanode master parameters > synchronous_standby_names='', then reload master postgresql.conf if > the master is running > 2、when starting datanode slave,prepare_startDatanodeSlave() change > master parameters synchronous_standby_names='datanode name' , but it > forget reload the master postgresql.conf, so the > synchronous_standby_names is invalid, replication is always > asynchronous, is it a bug of pgxc_ctl ? > > > -- > Thanks > Zhou Liang > > ------------------------------------------------------------------------------ > _______________________________________________ > Postgres-xc-bugs mailing list > Pos...@li... > https://lists.sourceforge.net/lists/listinfo/postgres-xc-bugs |
From: zhou l. <zh...@gm...> - 2014-08-19 14:40:47
|
Hi All, Datanode streaming replication state is async after pgxc_ctl command init all or start all。Datanode master sync_state is async in pg_stat_replication,as fallows : postgres=# select * from pg_stat_replication; pid | usesysid | usename | application_name | client_addr | client_hostname | client_port | backend_start | state | sent_location | write_location | flush_location | replay_location | sync_priority | sync_state ------+----------+---------+------------------+----------------+-----------------+-------------+-------------------------------+-----------+---------------+----------------+----------------+-----------------+---------------+------------ 2772 | 10 | postgres | datanode2 | 192.168.34.162 | | 51715 | 2014-08-20 04:35:39.561691+08 | streaming | 0/30011E8 | 0/30011E8 | 0/30011E8 | 0/30011B8 | 0 | async (1 row) postgres=# show synchronous_standby_names; synchronous_standby_names --------------------------- (1 row) behavior of pgxc_ctl : 1、when stoping datanode slave,prepare_stopDatanodeSlave() set the master to asynchronous mode by changing datanode master parameters synchronous_standby_names='', then reload master postgresql.conf if the master is running 2、when starting datanode slave,prepare_startDatanodeSlave() change master parameters synchronous_standby_names='datanode name' , but it forget reload the master postgresql.conf, so the synchronous_standby_names is invalid, replication is always asynchronous, is it a bug of pgxc_ctl ? -- Thanks Zhou Liang |
From: ZhangJulian <zh...@li...> - 2014-07-30 09:37:41
|
Hi All, I met the same error as the below link: https://sourceforge.net/p/postgres-xc/mailman/message/32017424/ And I have more error descritions: compile_option1: ./configure --prefix=/data/local/pgxc_local --enable-debug CFLAGS="-O0" compile_option2: ./configure --prefix=/data/local/pgxc_local --enable-debug RHEL6.4 with compile_option1: The error is not reproduced. RHEL6.4 with compile_option2: The error is not reproduced. RHEL7.0 with compile_option1: The error is not reproduced. RHEL7.0 with compile_option2: The error occurred. ============= 2014-07-31 00:50:21.760 CST:192.168.34.115(53993):[8600]: LOG: failed to find proc 0x7feaec14ae80 in ProcArray 2014-07-31 00:50:21.760 CST:192.168.34.115(53993):[8600]: STATEMENT: COMMIT PREPARED 'T2010' 2014-07-31 00:51:00.290 CST::[8679]: LOG: failed to find proc 0x7feaec101f40 in ProcArray 2014-07-31 00:52:00.357 CST::[8777]: LOG: failed to find proc 0x7feaec101f40 in ProcArray 2014-07-31 00:53:00.428 CST::[8933]: LOG: failed to find proc 0x7feaec101f40 in ProcArray 2014-07-31 00:53:59.498 CST::[9065]: LOG: failed to find proc 0x7feaec101f40 in ProcArray 2014-07-31 00:54:59.566 CST::[9143]: LOG: failed to find proc 0x7feaec101f40 in ProcArray 2014-07-31 00:55:59.633 CST::[9684]: LOG: failed to find proc 0x7feaec101f40 in ProcArray 2014-07-31 00:56:59.703 CST::[9761]: LOG: failed to find proc 0x7feaec101f40 in ProcArray 2014-07-31 00:57:59.771 CST::[9852]: LOG: failed to find proc 0x7feaec101f40 in ProcArray 2014-07-31 00:58:59.846 CST::[10508]: LOG: failed to find proc 0x7feaec101f40 in ProcArray 2014-07-31 00:59:59.917 CST::[10610]: LOG: failed to find proc 0x7feaec101f40 in ProcArray ================ Do you have some thoughts or some advice on how to debug it? Thanks Julian |
From: 鈴木 幸市 <ko...@in...> - 2014-07-22 09:48:35
|
2014/07/22 12:20、ZhangJulian <jul...@ou...<mailto:jul...@ou...>> のメール: Hi Koichi, Thanks for the reply! Then how to fix this type of issue? ================code segment1: if (TransactionIdIsValid(next_xid)) { xid = next_xid; elog(DEBUG1, "TransactionId = %d", next_xid); next_xid = InvalidTransactionId; /* reset */ if (!TransactionIdFollowsOrEquals(xid, ShmemVariableCache->nextXid)) { /* This should be ok, due to concurrency from multiple coords * passing down the xids. * We later do not want to bother incrementing the value * in shared memory though. */ increment_xid = false; elog(DEBUG1, "xid (%d) does not follow ShmemVariableCache->nextXid (%d)", xid, ShmemVariableCache->nextXid); } else ShmemVariableCache->nextXid = xid; } else { /* Fallback to default */ if (!useLocalXid) elog(LOG, "Falling back to local Xid. Was = %d, now is = %d", next_xid, ShmemVariableCache->nextXid); xid = ShmemVariableCache->nextXid; } The above else clause looks bad, as you suggested. =============== Just fix the ELSE branch by replacing it to a elog(ERROR, ...) ? ===============code segment2: if (MyPgXact->vacuumFlags & PROC_IN_VACUUM) next_xid = (TransactionId) BeginTranAutovacuumGTM(); else next_xid = (TransactionId) BeginTranGTM(timestamp); =============== Or fix the BeginTranAutovacuumGTM() and BeginTranGTM(timestamp) to ensure which return a valid xid? This is correct. Difference is that GXID for vacuum does not propagate to other TXN in snapshot. Although vacuum runs as a TXN, its GXID never appears in xmin or xmax. Vacuum is a long transaction and including this in a snapshot has bad affect to total performance. Regards; — Koichi Suzuki Thanks Julian ________________________________ From: ko...@in...<mailto:ko...@in...> To: jul...@ou...<mailto:jul...@ou...> CC: pos...@li...<mailto:pos...@li...> Subject: Re: [Postgres-xc-bugs] A stack trace for your investigating. Date: Tue, 22 Jul 2014 02:09:55 +0000 There’s still some code which falls to local XID. Initial XC code included such a fallback which should not happen and there must still be this type of code somewhere. Thank you. --- Koichi Suzuki 2014/07/21 13:08、ZhangJulian <jul...@ou...<mailto:jul...@ou...>> のメール: Hi All, It is hard to reproduce, just paste it here for your information. A autovacuum process got a invalid xid, then it fell back to a local xid. But the xid can not get the related Snapshot from GTM. It looks a design error, but I know little about the local transaction design. Is there any document talking about it? ===On the datanode: (gdb) bt #0 0x000000340b232925 in raise () from /lib64/libc.so.6 #1 0x000000340b234105 in abort () from /lib64/libc.so.6 #2 0x0000000000870fef in errfinish (dummy=0) at elog.c:566 #3 0x000000000087322f in elog_finish (elevel=22, fmt=0x8def08 "cannot abort transaction %u, it was already committed") at elog.c:1334 #4 0x00000000004cd162 in RecordTransactionAbort (isSubXact=0 '\000') at xact.c:1686 #5 0x00000000004ce48f in AbortTransaction () at xact.c:2998 #6 0x00000000004d00b8 in AbortOutOfAnyTransaction () at xact.c:4663 #7 0x0000000000883801 in ShutdownPostgres (code=0, arg=0) at postinit.c:1033 #8 0x0000000000738990 in shmem_exit (code=0) at ipc.c:221 #9 0x0000000000738892 in proc_exit_prepare (code=0) at ipc.c:181 #10 0x00000000007387f9 in proc_exit (code=0) at ipc.c:96 #11 0x00000000006f26f2 in AutoVacWorkerMain (argc=0, argv=0x0) at autovacuum.c:1566 #12 0x00000000006f258b in StartAutoVacWorker () at autovacuum.c:1464 #13 0x00000000007034f3 in StartAutovacuumWorker () at postmaster.c:5317 #14 0x0000000000702d8d in sigusr1_handler (postgres_signal_arg=10) at postmaster.c:4963 #15 <signal handler called> #16 0x000000340b2e15c3 in __select_nocancel () from /lib64/libc.so.6 #17 0x00000000006fea75 in ServerLoop () at postmaster.c:1662 #18 0x00000000006fe411 in PostmasterMain (argc=5, argv=0x2a4b790) at postmaster.c:1369 #19 0x000000000066326d in main (argc=5, argv=0x2a4b790) at main.c:206 ====Datanode Log: postgresql-2014-07-18_105851.log:14716 pgxc 2014-07-18 11:42:39 CSTLOG: statement: select autoanalyze_count from pg_stat_user_tables where schemaname = 'public' and relname = 'imei_historyseristatus' postgresql-2014-07-18_105851.log:14716 2014-07-18 13:09:22 CSTLOG: Falling back to local Xid. Was = 0, now is = 307616 postgresql-2014-07-18_105851.log:14716 2014-07-18 13:09:23 CSTERROR: GTM error, could not obtain snapshot postgresql-2014-07-18_105851.log:14716 2014-07-18 13:09:23 CSTPANIC: cannot abort transaction 307616, it was already committed postgresql-2014-07-18_105851.log:27533 2014-07-18 13:10:35 CSTLOG: server process (PID 14716) was terminated by signal 6: Aborted ====GTM Log: 1:140085928392448:2014-07-18 13:05:19.803 CST -LOG: Saving transaction restoration info, backed-up gxid: 308842 LOCATION: GTM_WriteRestorePointXid, gtm_txn.c:2649 1:140085928392448:2014-07-18 13:09:23.001 CST -WARNING: No transaction handle for gxid: 307616 LOCATION: GTM_GXIDToHandle, gtm_txn.c:163 1:140085928392448:2014-07-18 13:09:23.020 CST -WARNING: Invalid transaction handle: -1 LOCATION: GTM_HandleToTransactionInfo, gtm_txn.c:213 1:140085928392448:2014-07-18 13:09:23.068 CST -ERROR: Failed to get a snapshot LOCATION: ProcessGetSnapshotCommandMulti, gtm_snap.c:420 1:140085928392448:2014-07-18 13:18:44.968 CST -LOG: Saving transaction restoration info, backed-up gxid: 310846 Thanks Julian ------------------------------------------------------------------------------ Want fast and easy access to all the code in your enterprise? Index and search up to 200,000 lines of code with a free copy of Black Duck Code Sight - the same software that powers the world's largest code search on Ohloh, the Black Duck Open Hub! Try it now. http://p.sf.net/sfu/bds_______________________________________________ Postgres-xc-bugs mailing list Pos...@li...<mailto:Pos...@li...> https://lists.sourceforge.net/lists/listinfo/postgres-xc-bugs |
From: ZhangJulian <jul...@ou...> - 2014-07-22 03:20:18
|
Hi Koichi, Thanks for the reply! Then how to fix this type of issue? ================code segment1: if (TransactionIdIsValid(next_xid)) { xid = next_xid; elog(DEBUG1, "TransactionId = %d", next_xid); next_xid = InvalidTransactionId; /* reset */ if (!TransactionIdFollowsOrEquals(xid, ShmemVariableCache->nextXid)) { /* This should be ok, due to concurrency from multiple coords * passing down the xids. * We later do not want to bother incrementing the value * in shared memory though. */ increment_xid = false; elog(DEBUG1, "xid (%d) does not follow ShmemVariableCache->nextXid (%d)", xid, ShmemVariableCache->nextXid); } else ShmemVariableCache->nextXid = xid; } else { /* Fallback to default */ if (!useLocalXid) elog(LOG, "Falling back to local Xid. Was = %d, now is = %d", next_xid, ShmemVariableCache->nextXid); xid = ShmemVariableCache->nextXid; } =============== Just fix the ELSE branch by replacing it to a elog(ERROR, ...) ? ===============code segment2: if (MyPgXact->vacuumFlags & PROC_IN_VACUUM) next_xid = (TransactionId) BeginTranAutovacuumGTM(); else next_xid = (TransactionId) BeginTranGTM(timestamp); =============== Or fix the BeginTranAutovacuumGTM() and BeginTranGTM(timestamp) to ensure which return a valid xid? Thanks Julian From: ko...@in... To: jul...@ou... CC: pos...@li... Subject: Re: [Postgres-xc-bugs] A stack trace for your investigating. Date: Tue, 22 Jul 2014 02:09:55 +0000 There’s still some code which falls to local XID. Initial XC code included such a fallback which should not happen and there must still be this type of code somewhere. Thank you. --- Koichi Suzuki 2014/07/21 13:08、ZhangJulian <jul...@ou...> のメル: Hi All, It is hard to reproduce, just paste it here for your information. A autovacuum process got a invalid xid, then it fell back to a local xid. But the xid can not get the related Snapshot from GTM. It looks a design error, but I know little about the local transaction design. Is there any document talking about it? ===On the datanode: (gdb) bt #0 0x000000340b232925 in raise () from /lib64/libc.so.6 #1 0x000000340b234105 in abort () from /lib64/libc.so.6 #2 0x0000000000870fef in errfinish (dummy=0) at elog.c:566 #3 0x000000000087322f in elog_finish (elevel=22, fmt=0x8def08 "cannot abort transaction %u, it was already committed") at elog.c:1334 #4 0x00000000004cd162 in RecordTransactionAbort (isSubXact=0 '\000') at xact.c:1686 #5 0x00000000004ce48f in AbortTransaction () at xact.c:2998 #6 0x00000000004d00b8 in AbortOutOfAnyTransaction () at xact.c:4663 #7 0x0000000000883801 in ShutdownPostgres (code=0, arg=0) at postinit.c:1033 #8 0x0000000000738990 in shmem_exit (code=0) at ipc.c:221 #9 0x0000000000738892 in proc_exit_prepare (code=0) at ipc.c:181 #10 0x00000000007387f9 in proc_exit (code=0) at ipc.c:96 #11 0x00000000006f26f2 in AutoVacWorkerMain (argc=0, argv=0x0) at autovacuum.c:1566 #12 0x00000000006f258b in StartAutoVacWorker () at autovacuum.c:1464 #13 0x00000000007034f3 in StartAutovacuumWorker () at postmaster.c:5317 #14 0x0000000000702d8d in sigusr1_handler (postgres_signal_arg=10) at postmaster.c:4963 #15 <signal handler called> #16 0x000000340b2e15c3 in __select_nocancel () from /lib64/libc.so.6 #17 0x00000000006fea75 in ServerLoop () at postmaster.c:1662 #18 0x00000000006fe411 in PostmasterMain (argc=5, argv=0x2a4b790) at postmaster.c:1369 #19 0x000000000066326d in main (argc=5, argv=0x2a4b790) at main.c:206 ====Datanode Log: postgresql-2014-07-18_105851.log:14716 pgxc 2014-07-18 11:42:39 CSTLOG: statement: select autoanalyze_count from pg_stat_user_tables where schemaname = 'public' and relname = 'imei_historyseristatus' postgresql-2014-07-18_105851.log:14716 2014-07-18 13:09:22 CSTLOG: Falling back to local Xid. Was = 0, now is = 307616 postgresql-2014-07-18_105851.log:14716 2014-07-18 13:09:23 CSTERROR: GTM error, could not obtain snapshot postgresql-2014-07-18_105851.log:14716 2014-07-18 13:09:23 CSTPANIC: cannot abort transaction 307616, it was already committed postgresql-2014-07-18_105851.log:27533 2014-07-18 13:10:35 CSTLOG: server process (PID 14716) was terminated by signal 6: Aborted ====GTM Log: 1:140085928392448:2014-07-18 13:05:19.803 CST -LOG: Saving transaction restoration info, backed-up gxid: 308842 LOCATION: GTM_WriteRestorePointXid, gtm_txn.c:2649 1:140085928392448:2014-07-18 13:09:23.001 CST -WARNING: No transaction handle for gxid: 307616 LOCATION: GTM_GXIDToHandle, gtm_txn.c:163 1:140085928392448:2014-07-18 13:09:23.020 CST -WARNING: Invalid transaction handle: -1 LOCATION: GTM_HandleToTransactionInfo, gtm_txn.c:213 1:140085928392448:2014-07-18 13:09:23.068 CST -ERROR: Failed to get a snapshot LOCATION: ProcessGetSnapshotCommandMulti, gtm_snap.c:420 1:140085928392448:2014-07-18 13:18:44.968 CST -LOG: Saving transaction restoration info, backed-up gxid: 310846 Thanks Julian ------------------------------------------------------------------------------ Want fast and easy access to all the code in your enterprise? Index and search up to 200,000 lines of code with a free copy of Black Duck Code Sight - the same software that powers the world's largest code search on Ohloh, the Black Duck Open Hub! Try it now. http://p.sf.net/sfu/bds_______________________________________________ Postgres-xc-bugs mailing list Pos...@li... https://lists.sourceforge.net/lists/listinfo/postgres-xc-bugs |
From: 鈴木 幸市 <ko...@in...> - 2014-07-22 02:10:08
|
There’s still some code which falls to local XID. Initial XC code included such a fallback which should not happen and there must still be this type of code somewhere. Thank you. --- Koichi Suzuki 2014/07/21 13:08、ZhangJulian <jul...@ou...<mailto:jul...@ou...>> のメール: Hi All, It is hard to reproduce, just paste it here for your information. A autovacuum process got a invalid xid, then it fell back to a local xid. But the xid can not get the related Snapshot from GTM. It looks a design error, but I know little about the local transaction design. Is there any document talking about it? ===On the datanode: (gdb) bt #0 0x000000340b232925 in raise () from /lib64/libc.so.6 #1 0x000000340b234105 in abort () from /lib64/libc.so.6 #2 0x0000000000870fef in errfinish (dummy=0) at elog.c:566 #3 0x000000000087322f in elog_finish (elevel=22, fmt=0x8def08 "cannot abort transaction %u, it was already committed") at elog.c:1334 #4 0x00000000004cd162 in RecordTransactionAbort (isSubXact=0 '\000') at xact.c:1686 #5 0x00000000004ce48f in AbortTransaction () at xact.c:2998 #6 0x00000000004d00b8 in AbortOutOfAnyTransaction () at xact.c:4663 #7 0x0000000000883801 in ShutdownPostgres (code=0, arg=0) at postinit.c:1033 #8 0x0000000000738990 in shmem_exit (code=0) at ipc.c:221 #9 0x0000000000738892 in proc_exit_prepare (code=0) at ipc.c:181 #10 0x00000000007387f9 in proc_exit (code=0) at ipc.c:96 #11 0x00000000006f26f2 in AutoVacWorkerMain (argc=0, argv=0x0) at autovacuum.c:1566 #12 0x00000000006f258b in StartAutoVacWorker () at autovacuum.c:1464 #13 0x00000000007034f3 in StartAutovacuumWorker () at postmaster.c:5317 #14 0x0000000000702d8d in sigusr1_handler (postgres_signal_arg=10) at postmaster.c:4963 #15 <signal handler called> #16 0x000000340b2e15c3 in __select_nocancel () from /lib64/libc.so.6 #17 0x00000000006fea75 in ServerLoop () at postmaster.c:1662 #18 0x00000000006fe411 in PostmasterMain (argc=5, argv=0x2a4b790) at postmaster.c:1369 #19 0x000000000066326d in main (argc=5, argv=0x2a4b790) at main.c:206 ====Datanode Log: postgresql-2014-07-18_105851.log:14716 pgxc 2014-07-18 11:42:39 CSTLOG: statement: select autoanalyze_count from pg_stat_user_tables where schemaname = 'public' and relname = 'imei_historyseristatus' postgresql-2014-07-18_105851.log:14716 2014-07-18 13:09:22 CSTLOG: Falling back to local Xid. Was = 0, now is = 307616 postgresql-2014-07-18_105851.log:14716 2014-07-18 13:09:23 CSTERROR: GTM error, could not obtain snapshot postgresql-2014-07-18_105851.log:14716 2014-07-18 13:09:23 CSTPANIC: cannot abort transaction 307616, it was already committed postgresql-2014-07-18_105851.log:27533 2014-07-18 13:10:35 CSTLOG: server process (PID 14716) was terminated by signal 6: Aborted ====GTM Log: 1:140085928392448:2014-07-18 13:05:19.803 CST -LOG: Saving transaction restoration info, backed-up gxid: 308842 LOCATION: GTM_WriteRestorePointXid, gtm_txn.c:2649 1:140085928392448:2014-07-18 13:09:23.001 CST -WARNING: No transaction handle for gxid: 307616 LOCATION: GTM_GXIDToHandle, gtm_txn.c:163 1:140085928392448:2014-07-18 13:09:23.020 CST -WARNING: Invalid transaction handle: -1 LOCATION: GTM_HandleToTransactionInfo, gtm_txn.c:213 1:140085928392448:2014-07-18 13:09:23.068 CST -ERROR: Failed to get a snapshot LOCATION: ProcessGetSnapshotCommandMulti, gtm_snap.c:420 1:140085928392448:2014-07-18 13:18:44.968 CST -LOG: Saving transaction restoration info, backed-up gxid: 310846 Thanks Julian ------------------------------------------------------------------------------ Want fast and easy access to all the code in your enterprise? Index and search up to 200,000 lines of code with a free copy of Black Duck Code Sight - the same software that powers the world's largest code search on Ohloh, the Black Duck Open Hub! Try it now. http://p.sf.net/sfu/bds_______________________________________________ Postgres-xc-bugs mailing list Pos...@li... https://lists.sourceforge.net/lists/listinfo/postgres-xc-bugs |
From: ZhangJulian <jul...@ou...> - 2014-07-21 04:08:20
|
Hi All, It is hard to reproduce, just paste it here for your information. A autovacuum process got a invalid xid, then it fell back to a local xid. But the xid can not get the related Snapshot from GTM. It looks a design error, but I know little about the local transaction design. Is there any document talking about it? ===On the datanode: (gdb) bt #0 0x000000340b232925 in raise () from /lib64/libc.so.6 #1 0x000000340b234105 in abort () from /lib64/libc.so.6 #2 0x0000000000870fef in errfinish (dummy=0) at elog.c:566 #3 0x000000000087322f in elog_finish (elevel=22, fmt=0x8def08 "cannot abort transaction %u, it was already committed") at elog.c:1334 #4 0x00000000004cd162 in RecordTransactionAbort (isSubXact=0 '\000') at xact.c:1686 #5 0x00000000004ce48f in AbortTransaction () at xact.c:2998 #6 0x00000000004d00b8 in AbortOutOfAnyTransaction () at xact.c:4663 #7 0x0000000000883801 in ShutdownPostgres (code=0, arg=0) at postinit.c:1033 #8 0x0000000000738990 in shmem_exit (code=0) at ipc.c:221 #9 0x0000000000738892 in proc_exit_prepare (code=0) at ipc.c:181 #10 0x00000000007387f9 in proc_exit (code=0) at ipc.c:96 #11 0x00000000006f26f2 in AutoVacWorkerMain (argc=0, argv=0x0) at autovacuum.c:1566 #12 0x00000000006f258b in StartAutoVacWorker () at autovacuum.c:1464 #13 0x00000000007034f3 in StartAutovacuumWorker () at postmaster.c:5317 #14 0x0000000000702d8d in sigusr1_handler (postgres_signal_arg=10) at postmaster.c:4963 #15 <signal handler called> #16 0x000000340b2e15c3 in __select_nocancel () from /lib64/libc.so.6 #17 0x00000000006fea75 in ServerLoop () at postmaster.c:1662 #18 0x00000000006fe411 in PostmasterMain (argc=5, argv=0x2a4b790) at postmaster.c:1369 #19 0x000000000066326d in main (argc=5, argv=0x2a4b790) at main.c:206 ====Datanode Log: postgresql-2014-07-18_105851.log:14716 pgxc 2014-07-18 11:42:39 CSTLOG: statement: select autoanalyze_count from pg_stat_user_tables where schemaname = 'public' and relname = 'imei_historyseristatus' postgresql-2014-07-18_105851.log:14716 2014-07-18 13:09:22 CSTLOG: Falling back to local Xid. Was = 0, now is = 307616 postgresql-2014-07-18_105851.log:14716 2014-07-18 13:09:23 CSTERROR: GTM error, could not obtain snapshot postgresql-2014-07-18_105851.log:14716 2014-07-18 13:09:23 CSTPANIC: cannot abort transaction 307616, it was already committed postgresql-2014-07-18_105851.log:27533 2014-07-18 13:10:35 CSTLOG: server process (PID 14716) was terminated by signal 6: Aborted ====GTM Log: 1:140085928392448:2014-07-18 13:05:19.803 CST -LOG: Saving transaction restoration info, backed-up gxid: 308842 LOCATION: GTM_WriteRestorePointXid, gtm_txn.c:2649 1:140085928392448:2014-07-18 13:09:23.001 CST -WARNING: No transaction handle for gxid: 307616 LOCATION: GTM_GXIDToHandle, gtm_txn.c:163 1:140085928392448:2014-07-18 13:09:23.020 CST -WARNING: Invalid transaction handle: -1 LOCATION: GTM_HandleToTransactionInfo, gtm_txn.c:213 1:140085928392448:2014-07-18 13:09:23.068 CST -ERROR: Failed to get a snapshot LOCATION: ProcessGetSnapshotCommandMulti, gtm_snap.c:420 1:140085928392448:2014-07-18 13:18:44.968 CST -LOG: Saving transaction restoration info, backed-up gxid: 310846 Thanks Julian |
From: ZhangJulian <jul...@ou...> - 2014-07-14 01:58:59
|
When the query was running 3 hours, had you monitored the CPU and IO stats? Was it locked or running? Could you run EXPLAIN VERBOSE select..... to see what the remote query looks like? Thanks Julian Date: Fri, 11 Jul 2014 16:58:41 -0430 From: fab...@gm... To: pos...@li... Subject: [Postgres-xc-bugs] Coordinator never ends when executing multiple Join queries Queries with multiple Joins are giving me trouble. My postgres-xc configuration is as follows: 2 datanodes,1 coordinator,1 gtm Each on a different server. I have 5 tables loaded equally on both nodes: 1 replicated and 4 distributed by hash on the correspondent Join attributes. When I run the query on a simple PostgreSQL server, it takes about 20 seconds to finish the execution, but it seems like it will never come to an end whenever I run the query on my postgres-xc server; I have waited over three hours waiting for it to end. Nevertheless, if I do "EXECUTE DIRECT ON node# 'query'", it takes up to 5 seconds tops on both nodes. Suppose my tables are...tableR --- Replicated table table1 --- distributed by hash on (id)table2, table3 & table4 --- distributed by hash on (t1id) ... And:table1 has 2200000 recordstable2 has 2160000 recordstable3 has 2190000 recordstable4 has 6596 recordstableR has 223 records The query is basically something like this: SELECT COUNT(*) FROM table1JOIN table2 ON table2.t1id = table1.id LEFT OUTER JOIN table3 ON table3.t1id = table1.id LEFT OUTER JOIN table4 ON table4.t1id = table1.id LEFT OUTER JOIN tableR ON tableR.id = table4.tRid; Thank you very much,Fabiola Rosato. ------------------------------------------------------------------------------ _______________________________________________ Postgres-xc-bugs mailing list Pos...@li... https://lists.sourceforge.net/lists/listinfo/postgres-xc-bugs |
From: Fabiola R. <fab...@gm...> - 2014-07-11 21:28:49
|
Queries with multiple Joins are giving me trouble. My postgres-xc configuration is as follows: 2 datanodes, 1 coordinator, 1 gtm Each on a different server. I have 5 tables loaded equally on both nodes: 1 replicated and 4 distributed by hash on the correspondent Join attributes. When I run the query on a simple PostgreSQL server, it takes about 20 seconds to finish the execution, but it seems like it will never come to an end whenever I run the query on my postgres-xc server; I have waited over three hours waiting for it to end. Nevertheless, if I do "EXECUTE DIRECT ON node# 'query'", it takes up to 5 seconds tops on both nodes. Suppose my tables are... tableR --- Replicated table table1 --- distributed by hash on (id) table2, table3 & table4 --- distributed by hash on (t1id) ... And: table1 has 2200000 records table2 has 2160000 records table3 has 2190000 records table4 has 6596 records tableR has 223 records The query is basically something like this: SELECT COUNT(*) FROM table1 JOIN table2 ON table2.t1id = table1.id LEFT OUTER JOIN table3 ON table3.t1id = table1.id LEFT OUTER JOIN table4 ON table4.t1id = table1.id LEFT OUTER JOIN tableR ON tableR.id = table4.tRid; Thank you very much, Fabiola Rosato. |
From: ZhangJulian <jul...@ou...> - 2014-07-04 09:42:12
|
Hi Koichi, Because in this case, it is an UPDATE statement, so root->rowMarks is null, and separatem_rowmarks() is not applicable here. My patch is in pgxc_build_shippable_query_baserel(), which will add "FOR UDPATE" to a remote SELECT query only when the original statemetn is a UPDATE. I feel the patch is ok, but "make check" test got many "deadlock" errors. Currently, I can do nothing except rewriting the query to work around the bug. Rewrite: UPDATE ... RETURNING ... To: SELECT ... INTO ... FOR UPDATE; UPDATE.... I plan to look the deadlock issue next step, but it seems a bit difficult to me. :) Thanks Julian From: ko...@in... To: jul...@ou... CC: pos...@li... Subject: Re: [Postgres-xc-bugs] Fix a bug about UPDATE ... RETURNNING... Date: Fri, 4 Jul 2014 02:51:48 +0000 Thanks a lot for finding the bug and the patch. Addition of “FOR UPDATE” is controlled by separatem_rowmarks() in planner.c, which is specific to XC. Could you please review this function as well as subquery_planner() calling this function and see if your patch does not conflict with them? Best Regards; --- Koichi Suzuki 2014/07/03 15:04、ZhangJulian <jul...@ou...> のメル: Hi all, I found a bug and made a fix, but need your review since I am not familar with big picture of the Optimizer. The reproduced steps: create table t1 (c1 int, c2 int) distribute by hash(c1); insert into t1 values(1,1); Then you run a UPDATE statement 10 times, the c2 is expected to be added to 11. for i in `seq 1 10`; do psql postgres -c "update t1 set c2 = c2 + 1 where c1 = 1 returning c2" & done But unfortunately the c2 is just added to 2. The error can be examined from the below explained plan: postgres=# explain verbose update t1 set c2 = c2 + 1 where c1 = 1 returning c2; QUERY PLAN ---------------------------------------------------------------------------------------------------------------------------- Update on public.t1 (cost=0.00..2.50 rows=1000 width=18) Output: t1.c2 Node/s: datanode1, datanode2 Node expr: t1.c1 Remote query: UPDATE ONLY public.t1 SET c1 = $1, c2 = $2 WHERE ((t1.ctid = $3) AND (t1.xc_node_id = $4)) RETURNING t1.c2 -> Data Node Scan on t1 "_REMOTE_TABLE_QUERY_" (cost=0.00..2.50 rows=1000 width=18) Output: t1.c1, (t1.c2 + 1), t1.c1, t1.ctid, t1.xc_node_id Node/s: datanode1 Remote query: SELECT c1, c2, ctid, xc_node_id FROM ONLY public.t1 WHERE (c1 = 1) (9 rows) The remote query has no FOR UPDATE clause, so all parallel UPDATE statements got the same initial c2 value(that is 1), and do UPDATE it to 2. I made the fix as the append patch file, then the explained plan is changed as below. postgres=# explain verbose update t1 set c2 = c2 + 1 where c1 = 1 returning c2; QUERY PLAN ---------------------------------------------------------------------------------------------------------------------------- Update on public.t1 (cost=0.00..2.50 rows=1000 width=18) Output: t1.c2 Node/s: datanode1, datanode2 Node expr: t1.c1 Remote query: UPDATE ONLY public.t1 SET c1 = $1, c2 = $2 WHERE ((t1.ctid = $3) AND (t1.xc_node_id = $4)) RETURNING t1.c2 -> Data Node Scan on t1 "_REMOTE_TABLE_QUERY_" (cost=0.00..2.50 rows=1000 width=18) Output: t1.c1, (t1.c2 + 1), t1.c1, t1.ctid, t1.xc_node_id Node/s: datanode1 Remote query: SELECT c1, c2, ctid, xc_node_id FROM ONLY public.t1 WHERE (c1 = 1) FOR UPDATE OF t1 (9 rows) When I run the command below again, for i in `seq 1 10`; do psql postgres -c "update t1 set c2 = c2 + 1 where c1 = 1 returning c2" & done Only one statement return succussfully, and other statements got WARNING and ERROR displayed as the append file error.txt. Do you think it is the expected results? Thanks Julian <20140703_update_with_returnning.patch><error.txt>------------------------------------------------------------------------------ Open source business process management suite built on Java and Eclipse Turn processes into business applications with Bonita BPM Community Edition Quickly connect people, data, and systems into organized workflows Winner of BOSSIE, CODIE, OW2 and Gartner awards http://p.sf.net/sfu/Bonitasoft_______________________________________________ Postgres-xc-bugs mailing list Pos...@li... https://lists.sourceforge.net/lists/listinfo/postgres-xc-bugs |
From: 鈴木 幸市 <ko...@in...> - 2014-07-04 02:51:59
|
Thanks a lot for finding the bug and the patch. Addition of “FOR UPDATE” is controlled by separatem_rowmarks() in planner.c, which is specific to XC. Could you please review this function as well as subquery_planner() calling this function and see if your patch does not conflict with them? Best Regards; --- Koichi Suzuki 2014/07/03 15:04、ZhangJulian <jul...@ou...<mailto:jul...@ou...>> のメール: Hi all, I found a bug and made a fix, but need your review since I am not familar with big picture of the Optimizer. The reproduced steps: create table t1 (c1 int, c2 int) distribute by hash(c1); insert into t1 values(1,1); Then you run a UPDATE statement 10 times, the c2 is expected to be added to 11. for i in `seq 1 10`; do psql postgres -c "update t1 set c2 = c2 + 1 where c1 = 1 returning c2" & done But unfortunately the c2 is just added to 2. The error can be examined from the below explained plan: postgres=# explain verbose update t1 set c2 = c2 + 1 where c1 = 1 returning c2; QUERY PLAN ---------------------------------------------------------------------------------------------------------------------------- Update on public.t1 (cost=0.00..2.50 rows=1000 width=18) Output: t1.c2 Node/s: datanode1, datanode2 Node expr: t1.c1 Remote query: UPDATE ONLY public.t1 SET c1 = $1, c2 = $2 WHERE ((t1.ctid = $3) AND (t1.xc_node_id = $4)) RETURNING t1.c2 -> Data Node Scan on t1 "_REMOTE_TABLE_QUERY_" (cost=0.00..2.50 rows=1000 width=18) Output: t1.c1, (t1.c2 + 1), t1.c1, t1.ctid, t1.xc_node_id Node/s: datanode1 Remote query: SELECT c1, c2, ctid, xc_node_id FROM ONLY public.t1 WHERE (c1 = 1) (9 rows) The remote query has no FOR UPDATE clause, so all parallel UPDATE statements got the same initial c2 value(that is 1), and do UPDATE it to 2. I made the fix as the append patch file, then the explained plan is changed as below. postgres=# explain verbose update t1 set c2 = c2 + 1 where c1 = 1 returning c2; QUERY PLAN ---------------------------------------------------------------------------------------------------------------------------- Update on public.t1 (cost=0.00..2.50 rows=1000 width=18) Output: t1.c2 Node/s: datanode1, datanode2 Node expr: t1.c1 Remote query: UPDATE ONLY public.t1 SET c1 = $1, c2 = $2 WHERE ((t1.ctid = $3) AND (t1.xc_node_id = $4)) RETURNING t1.c2 -> Data Node Scan on t1 "_REMOTE_TABLE_QUERY_" (cost=0.00..2.50 rows=1000 width=18) Output: t1.c1, (t1.c2 + 1), t1.c1, t1.ctid, t1.xc_node_id Node/s: datanode1 Remote query: SELECT c1, c2, ctid, xc_node_id FROM ONLY public.t1 WHERE (c1 = 1) FOR UPDATE OF t1 (9 rows) When I run the command below again, for i in `seq 1 10`; do psql postgres -c "update t1 set c2 = c2 + 1 where c1 = 1 returning c2" & done Only one statement return succussfully, and other statements got WARNING and ERROR displayed as the append file error.txt. Do you think it is the expected results? Thanks Julian <20140703_update_with_returnning.patch><error.txt>------------------------------------------------------------------------------ Open source business process management suite built on Java and Eclipse Turn processes into business applications with Bonita BPM Community Edition Quickly connect people, data, and systems into organized workflows Winner of BOSSIE, CODIE, OW2 and Gartner awards http://p.sf.net/sfu/Bonitasoft_______________________________________________ Postgres-xc-bugs mailing list Pos...@li... https://lists.sourceforge.net/lists/listinfo/postgres-xc-bugs |
From: ZhangJulian <jul...@ou...> - 2014-07-03 06:05:07
|
[zhangzl@compute-22-05 PGXC]$ for i in `seq 1 10`; do psql postgres -c "update t1 set c2 = c2 + 1 where c1 = 1 returning c2" & done [1] 10046 [2] 10047 [3] 10048 [4] 10049 [5] 10050 [6] 10051 [7] 10052 [8] 10053 [9] 10054 [10] 10055 [zhangzl@compute-22-05 PGXC]$ c2 ---- 18 (1 row) UPDATE 1 ERROR: deadlock detected DETAIL: Process 10080 waits for AccessExclusiveLock on tuple (0,35) of relation 16648 of database 12919; blocked by process 10079. Process 10079 waits for ShareLock on transaction 44113; blocked by process 10070. Process 10070 waits for ExclusiveLock on tuple (0,35) of relation 16648 of database 12919; blocked by process 10080. ERROR: deadlock detected DETAIL: Process 10081 waits for AccessExclusiveLock on tuple (0,35) of relation 16648 of database 12919; blocked by process 10079. Process 10079 waits for ShareLock on transaction 44113; blocked by process 10070. Process 10070 waits for ExclusiveLock on tuple (0,35) of relation 16648 of database 12919; blocked by process 10081. ERROR: deadlock detected DETAIL: Process 10082 waits for AccessExclusiveLock on tuple (0,35) of relation 16648 of database 12919; blocked by process 10079. Process 10079 waits for ShareLock on transaction 44113; blocked by process 10070. Process 10070 waits for ExclusiveLock on tuple (0,35) of relation 16648 of database 12919; blocked by process 10082. ERROR: deadlock detected DETAIL: Process 10083 waits for AccessExclusiveLock on tuple (0,35) of relation 16648 of database 12919; blocked by process 10079. Process 10079 waits for ShareLock on transaction 44113; blocked by process 10070. Process 10070 waits for ExclusiveLock on tuple (0,35) of relation 16648 of database 12919; blocked by process 10083. ERROR: deadlock detected DETAIL: Process 10084 waits for AccessExclusiveLock on tuple (0,35) of relation 16648 of database 12919; blocked by process 10079. Process 10079 waits for ShareLock on transaction 44113; blocked by process 10070. Process 10070 waits for ExclusiveLock on tuple (0,35) of relation 16648 of database 12919; blocked by process 10084. ERROR: deadlock detected DETAIL: Process 10085 waits for AccessExclusiveLock on tuple (0,35) of relation 16648 of database 12919; blocked by process 10079. Process 10079 waits for ShareLock on transaction 44113; blocked by process 10070. Process 10070 waits for ExclusiveLock on tuple (0,35) of relation 16648 of database 12919; blocked by process 10085. WARNING: unexpected EOF on datanode connection ERROR: deadlock detected DETAIL: Process 10070 waits for ExclusiveLock on tuple (0,35) of relation 16648 of database 12919; blocked by process 10079. Process 10079 waits for ShareLock on transaction 44113; blocked by process 10070. WARNING: unexpected EOF on datanode connection WARNING: unexpected EOF on datanode connection ERROR: Failed to read response from Datanodes WARNING: unexpected EOF on datanode connection ERROR: Failed to read response from Datanodes [1] Exit 1 psql postgres -c "update t1 set c2 = c2 + 1 where c1 = 1 returning c2" [2] Exit 1 psql postgres -c "update t1 set c2 = c2 + 1 where c1 = 1 returning c2" [3] Exit 1 psql postgres -c "update t1 set c2 = c2 + 1 where c1 = 1 returning c2" [4] Exit 1 psql postgres -c "update t1 set c2 = c2 + 1 where c1 = 1 returning c2" [5] Exit 1 psql postgres -c "update t1 set c2 = c2 + 1 where c1 = 1 returning c2" [6] Exit 1 psql postgres -c "update t1 set c2 = c2 + 1 where c1 = 1 returning c2" [7] Done psql postgres -c "update t1 set c2 = c2 + 1 where c1 = 1 returning c2" [8] Exit 1 psql postgres -c "update t1 set c2 = c2 + 1 where c1 = 1 returning c2" [9]- Exit 1 psql postgres -c "update t1 set c2 = c2 + 1 where c1 = 1 returning c2" [10]+ Exit 1 psql postgres -c "update t1 set c2 = c2 + 1 where c1 = 1 returning c2" |
From: Koichi S. <koi...@gm...> - 2014-06-23 01:58:32
|
Thanks Zhang for the patch. It looks reasonable to me. Ashutosh, your thoughts? Regards; --- Koichi Suzuki 2014-06-19 19:06 GMT+09:00 ZhangJulian <jul...@ou...>: > Hi All, > > The error is as following: > ================================ > postgres=# create table t1(c1 varchar(10)); > CREATE TABLE > postgres=# create table t2(c1 varchar(10)); > CREATE TABLE > postgres=# > postgres=# > postgres=# explain verbose select * from t1,t2 where t1.c1=t2.c1; > QUERY PLAN > ------------------------------------------------------------------------------------------------- > Hash Join (cost=0.12..0.26 rows=10 width=76) > Output: t1.c1, t2.c1 > Hash Cond: ((t1.c1)::text = (t2.c1)::text) > -> Data Node Scan on t1 "_REMOTE_TABLE_QUERY_" (cost=0.00..0.00 > rows=1000 width=38) > Output: t1.c1 > Node/s: datanode1, datanode2 > Remote query: SELECT c1 FROM ONLY public.t1 WHERE true > -> Hash (cost=0.00..0.00 rows=1000 width=38) > Output: t2.c1 > -> Data Node Scan on t2 "_REMOTE_TABLE_QUERY__1" (cost=0.00..0.00 > rows=1000 width=38) > Output: t2.c1 > Node/s: datanode1, datanode2 > Remote query: SELECT c1 FROM ONLY public.t2 WHERE true > (13 rows) > ===================================== > > If two sides of a join are of VARCHAR type, even they are distribute keys of > both table, the JOIN still can not been pushed to Datanode. > I tried to fix it as the appended patch, please advise if it is correct! > > After applying the patch: > ===================================== > postgres=# explain verbose select * from t1,t2 where t1.c1=t2.c1; > QUERY PLAN > ----------------------------------------------------------------------------------------------------- > Data Node Scan on "__REMOTE_FQS_QUERY__" (cost=0.00..0.00 rows=0 width=0) > Output: t1.c1, t2.c1 > Node/s: datanode1, datanode2 > Remote query: SELECT t1.c1, t2.c1 FROM public.t1, public.t2 WHERE > ((t1.c1)::text = (t2.c1)::text) > (4 rows) > ======================================== > > Thanks > Julian > > > ------------------------------------------------------------------------------ > HPCC Systems Open Source Big Data Platform from LexisNexis Risk Solutions > Find What Matters Most in Your Big Data with HPCC Systems > Open Source. Fast. Scalable. Simple. Ideal for Dirty Data. > Leverages Graph Analysis for Fast Processing & Easy Data Exploration > http://p.sf.net/sfu/hpccsystems > _______________________________________________ > Postgres-xc-bugs mailing list > Pos...@li... > https://lists.sourceforge.net/lists/listinfo/postgres-xc-bugs > |