GitHub user leborchuk added a comment to the discussion: [Ideas] Add instrumentation and latency metrics to the Anser subsystem
The examples of data on my dev demo cluster 1. How to trace - `set anser.debug=on;` 2. Example of raw data from logs ``` /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.527686 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: producer init cond=0 part=0/1 elems=3334 payload=67108928 state=ok",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.551469 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD part cond=0 from seg2 (says part 2 of 3) 1/3 bytes=1048592 -> collecting",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.558633 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD part cond=0 from seg0 (says part 0 of 3) 2/3 bytes=1048592 -> collecting",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.558684 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD subscribe cond=0 from seg0 (channel still collecting)",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.558712 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD subscribe cond=0 from seg1 (channel still collecting)",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.558737 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD subscribe cond=0 from seg2 (channel still collecting)",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.565990 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD part cond=0 from seg1 (says part 1 of 3) 3/3 bytes=1048592 -> complete",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.566018 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD delivering cond=0 to 3 subscriber(s)",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.566477 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD pushed cond=0 bytes=1048592 cancelled=0",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.566860 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD pushed cond=0 bytes=1048592 cancelled=0",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/qddir/demoDataDir-1/log/gpdb-2026-09-07_112618.csv:2026-09-07 11:27:19.567277 UTC,"xifos","postgres",p88346,th706219584,"[local]",,2026-09-07 11:26:32 UTC,0,con23,cmd6,seg-1,,,,sx1,"LOG","00000","anser: QD pushed cond=0 bytes=1048592 cancelled=0",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast1/demoDataDir0/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.534745 UTC,"xifos","postgres",p88524,th1725312576,"127.0.0.1","56156",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg0,slice2,,,sx1,"LOG","00000","anser: producer init cond=0 part=0/3 elems=3334 payload=67108928 state=ok",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast1/demoDataDir0/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.536508 UTC,"xifos","postgres",p88524,th1725312576,"127.0.0.1","56156",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg0,slice2,,,sx1,"LOG","00000","anser: producer child exhausted, publishing (state=ok)",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast1/demoDataDir0/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.543574 UTC,"xifos","postgres",p88524,th1725312576,"127.0.0.1","56156",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg0,slice2,,,sx1,"LOG","00000","anser: seg0 published cond=0 part=0/3 bytes=1048592 cancelled=0 sent=1",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast1/demoDataDir0/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.544858 UTC,"xifos","postgres",p88378,th1725312576,"127.0.0.1","59664",2026-09-07 11:26:40 UTC,0,con23,cmd6,seg0,slice1,,,sx1,"LOG","00000","anser: seg0 subscribed cond=0, waiting up to 1000 ms",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast1/demoDataDir0/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.567852 UTC,"xifos","postgres",p88378,th1725312576,"127.0.0.1","59664",2026-09-07 11:26:40 UTC,0,con23,cmd6,seg0,slice1,,,sx1,"LOG","00000","anser: seg0 received cond=0 bytes=1048592 cancelled=0",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast2/demoDataDir1/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.534632 UTC,"xifos","postgres",p88525,th867016256,"127.0.0.1","33560",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg1,slice2,,,sx1,"LOG","00000","anser: producer init cond=0 part=1/3 elems=3334 payload=67108928 state=ok",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast2/demoDataDir1/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.538237 UTC,"xifos","postgres",p88525,th867016256,"127.0.0.1","33560",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg1,slice2,,,sx1,"LOG","00000","anser: producer child exhausted, publishing (state=ok)",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast2/demoDataDir1/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.544624 UTC,"xifos","postgres",p88525,th867016256,"127.0.0.1","33560",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg1,slice2,,,sx1,"LOG","00000","anser: seg1 published cond=0 part=1/3 bytes=1048592 cancelled=0 sent=1",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast2/demoDataDir1/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.544876 UTC,"xifos","postgres",p88380,th867016256,"127.0.0.1","55068",2026-09-07 11:26:40 UTC,0,con23,cmd6,seg1,slice1,,,sx1,"LOG","00000","anser: seg1 subscribed cond=0, waiting up to 1000 ms",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast2/demoDataDir1/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.568240 UTC,"xifos","postgres",p88380,th867016256,"127.0.0.1","55068",2026-09-07 11:26:40 UTC,0,con23,cmd6,seg1,slice1,,,sx1,"LOG","00000","anser: seg1 received cond=0 bytes=1048592 cancelled=0",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast3/demoDataDir2/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.534629 UTC,"xifos","postgres",p88526,th72871488,"127.0.0.1","47130",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg2,slice2,,,sx1,"LOG","00000","anser: producer init cond=0 part=2/3 elems=3334 payload=67108928 state=ok",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast3/demoDataDir2/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.536992 UTC,"xifos","postgres",p88526,th72871488,"127.0.0.1","47130",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg2,slice2,,,sx1,"LOG","00000","anser: producer child exhausted, publishing (state=ok)",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast3/demoDataDir2/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.543316 UTC,"xifos","postgres",p88526,th72871488,"127.0.0.1","47130",2026-09-07 11:27:19 UTC,0,con23,cmd6,seg2,slice2,,,sx1,"LOG","00000","anser: seg2 published cond=0 part=2/3 bytes=1048592 cancelled=0 sent=1",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast3/demoDataDir2/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.544872 UTC,"xifos","postgres",p88379,th72871488,"127.0.0.1","46024",2026-09-07 11:26:40 UTC,0,con23,cmd6,seg2,slice1,,,sx1,"LOG","00000","anser: seg2 subscribed cond=0, waiting up to 1000 ms",,,,,,"explain analyze select /home/xifos/git/cloudberry/gpAux/gpdemo/datadirs/dbfast3/demoDataDir2/log/gpdb-2026-09-07_112617.csv:2026-09-07 11:27:19.568601 UTC,"xifos","postgres",p88379,th72871488,"127.0.0.1","46024",2026-09-07 11:26:40 UTC,0,con23,cmd6,seg2,slice1,,,sx1,"LOG","00000","anser: seg2 received cond=0 bytes=1048592 cancelled=0",,,,,,"explain analyze select ``` 3. The conslusion based on debug data Three-way events show the spread across segments: ``` ┌─────────────┬────────────────────────────────────────────────────┐ │ t (ms) │ Event │ ├─────────────┼────────────────────────────────────────────────────┤ │ 0.0 │ 3 producers init — part=0/3, 1/3, 2/3 (spread 0.1) │ ├─────────────┼────────────────────────────────────────────────────┤ │ 1.9 – 3.6 │ children exhausted, publishing (seg0, seg2, seg1) │ ├─────────────┼────────────────────────────────────────────────────┤ │ 8.7 – 10.0 │ all 3 published, sent=1 (seg2, seg0, seg1) │ ├─────────────┼────────────────────────────────────────────────────┤ │ 10.2 – 10.2 │ 3 consumers subscribe (spread 0.02) │ ├─────────────┼────────────────────────────────────────────────────┤ │ 16.8 │ QD folds seg2 → 1/3 collecting │ ├─────────────┼────────────────────────────────────────────────────┤ │ 24.0 │ QD folds seg0 → 2/3 collecting │ ├─────────────┼────────────────────────────────────────────────────┤ │ 24.1 │ QD receives the 3 subscribes (spread 0.05) │ ├─────────────┼────────────────────────────────────────────────────┤ │ 31.4 │ QD folds seg1 → 3/3 complete │ ├─────────────┼────────────────────────────────────────────────────┤ │ 31.4 │ QD delivering to 3 subscribers │ ├─────────────┼────────────────────────────────────────────────────┤ │ 31.8 – 32.6 │ 3 pushes, 1048592 bytes each │ ├─────────────┼────────────────────────────────────────────────────┤ │ 33.2 – 34.0 │ all 3 consumers received │ └─────────────┴────────────────────────────────────────────────────┘ ``` 34.0 ms first-init to last-received; 25.3 ms publish to received. One thing that jumps out now that it's relative: the three parts were sent within 1.3 ms of each other (8.7 → 10.0) but folded 16.8 → 31.4, evenly spaced about 7.2 ms apart. So roughly 21 ms of the 34 is the coordinator picking parts up one at a time, not doing work — a 1 MB fold is ~0.1 ms and a 1.4 MB base64 decode ~1–2 ms. That points at the drain cadence: one part per processResults sweep, gated by the interconnect wait loop rather than by anything Anser does. What I want - could gather the similar info without enabling debug mode and processing raw debug info GitHub link: https://github.com/apache/cloudberry/discussions/1958#discussioncomment-18333241 ---- This is an automatically sent email for [email protected]. To unsubscribe, please send an email to: [email protected] --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
