So, I’m submitting a (performance tracking) transaction to Sentry and it takes almost a minute to actually show up in Discover.
Here’s a snippet from my logs:
clickhouse_1 | 2021.08.11 21:45:59.694727 [ 117 ] {4c629e29992f1cb0b481a647a364c38d} <Information> executeQuery: Read 8209 rows, 64.71 KiB in 0.010 sec., 862327 rows/sec., 6.64 MiB/sec.
clickhouse_1 | 2021.08.11 21:45:59.696399 [ 117 ] {} <Information> TCPHandler: Processed in 0.012 sec.
clickhouse_1 | 2021.08.11 21:45:59.744351 [ 117 ] {42ecebe477554b23ece2f7c0ad815452} <Information> executeQuery: Read 8209 rows, 64.71 KiB in 0.018 sec., 464075 rows/sec., 3.57 MiB/sec.
clickhouse_1 | 2021.08.11 21:45:59.745453 [ 117 ] {} <Information> TCPHandler: Processed in 0.021 sec.
clickhouse_1 | 2021.08.11 21:45:59.793066 [ 117 ] {cc354e19621fa7e3c33e0e03c8313da2} <Information> executeQuery: Read 8209 rows, 66.55 KiB in 0.009 sec., 886699 rows/sec., 7.02 MiB/sec.
clickhouse_1 | 2021.08.11 21:45:59.793488 [ 117 ] {} <Information> TCPHandler: Processed in 0.010 sec.
clickhouse_1 | 2021.08.11 21:45:59.836833 [ 117 ] {41fd3cd8a55d1dbe2f52d210c5902ae1} <Information> executeQuery: Read 8209 rows, 143.74 KiB in 0.027 sec., 306164 rows/sec., 5.24 MiB/sec.
clickhouse_1 | 2021.08.11 21:45:59.839103 [ 117 ] {} <Information> TCPHandler: Processed in 0.031 sec.
clickhouse_1 | 2021.08.11 21:46:00.280479 [ 111 ] {eef9f131-a855-4fb3-957b-a39b6543882d} <Information> executeQuery: Read 1 rows, 185.00 B in 0.015 sec., 68 rows/sec., 12.36 KiB/sec.
clickhouse_1 | 2021.08.11 21:46:00.281665 [ 111 ] {} <Information> HTTPHandler: Done processing query
snuba-sessions-consumer_1 | 2021-08-11 21:46:00,283 Completed processing <Batch: 1 message, open for 1.02 seconds>.
clickhouse_1 | 2021.08.11 21:46:17.090339 [ 117 ] {c3aff2c180bcab20703c5720e1299794} <Information> executeQuery: Read 8210 rows, 64.72 KiB in 0.009 sec., 869748 rows/sec., 6.70 MiB/sec.
clickhouse_1 | 2021.08.11 21:46:17.090721 [ 117 ] {} <Information> TCPHandler: Processed in 0.011 sec.
clickhouse_1 | 2021.08.11 21:46:17.124092 [ 117 ] {13c49794ecc4be8a1e92113ae63a95d5} <Information> executeQuery: Read 8210 rows, 66.58 KiB in 0.010 sec., 795083 rows/sec., 6.30 MiB/sec.
clickhouse_1 | 2021.08.11 21:46:17.125027 [ 117 ] {} <Information> TCPHandler: Processed in 0.012 sec.
clickhouse_1 | 2021.08.11 21:46:17.160097 [ 117 ] {f7bb2b38c161f9a9b993dc0f91cf3aa0} <Information> executeQuery: Read 8210 rows, 143.87 KiB in 0.019 sec., 429965 rows/sec., 7.36 MiB/sec.
clickhouse_1 | 2021.08.11 21:46:17.161243 [ 117 ] {} <Information> TCPHandler: Processed in 0.022 sec.
clickhouse_1 | 2021.08.11 21:46:17.196670 [ 117 ] {95fae8f8abf863676e92fdaf41146c29} <Information> executeQuery: Read 8210 rows, 64.72 KiB in 0.011 sec., 725791 rows/sec., 5.59 MiB/sec.
clickhouse_1 | 2021.08.11 21:46:17.197143 [ 117 ] {} <Information> TCPHandler: Processed in 0.013 sec.
clickhouse_1 | 2021.08.11 21:46:17.487675 [ 110 ] {f607e61e-59b1-4129-aa22-292a6caba26e} <Information> executeQuery: Read 1 rows, 185.00 B in 0.018 sec., 55 rows/sec., 10.03 KiB/sec.
clickhouse_1 | 2021.08.11 21:46:17.489095 [ 110 ] {} <Information> HTTPHandler: Done processing query
snuba-sessions-consumer_1 | 2021-08-11 21:46:17,490 Completed processing <Batch: 1 message, open for 1.02 seconds>.
Those two (almost) identical blocks are from two page reloads of the Discover page. I noticed that the moment when a new transaction shows up in the list always coincides with the “Read XXXX rows” number increasing. Like, you see how it changes from “Read 8209 rows” to “Read 8210 rows” in the log? That is when the transaction shows up in the list. I just don’t know what triggers that and why it isn’t triggered earlier.
I have checked if maybe there is some process actually working (CPU/IO) during that delay time, but it isn’t. So there must be some time-based trigger or something.