Alexey Serbin has uploaded this change for review. ( http://gerrit.cloudera.org:8080/20232
Change subject: [tablet] add more details for operation's APPLY trace ...................................................................... [tablet] add more details for operation's APPLY trace While troubleshooting a performance issue, I saw a trace like below where it wasn't possible to tell what exact part of the APPLY phase too very long. This patch adds more tracing around BulkCheckPresence() and ApplyRowOperation(), so now it will be possible to tell between the two. I also took the liberty to update other tracing messages, making their style more uniform. W0717 00:13:03.171553 34715 rpcz_store.cc:260] Trace: 0716 23:58:44.240887 (+ 0us) service_pool.cc:169] Inserting onto call queue 0716 23:58:44.240902 (+ 15us) service_pool.cc:228] Handling call 0717 00:13:03.171190 (+858930288us) inbound_call.cc:171] Queueing success response Related trace 'op': 0716 23:58:44.241244 (+ 0us) write_op.cc:162] PREPARE: Starting. 0716 23:58:44.241285 (+ 41us) write_op.cc:383] Acquiring schema lock in shared mode 0716 23:58:44.241286 (+ 1us) write_op.cc:386] Acquired schema lock 0716 23:58:44.241287 (+ 1us) tablet.cc:541] Decoding operations 0716 23:58:44.241315 (+ 28us) write_op.cc:558] Acquiring the partition lock for write op 0716 23:58:44.241316 (+ 1us) write_op.cc:579] Partition lock acquired for write op 0716 23:58:44.241316 (+ 0us) tablet.cc:563] Acquiring locks for 1 operations 0716 23:58:44.241325 (+ 9us) tablet.cc:579] Row locks acquired 0716 23:58:44.241325 (+ 0us) write_op.cc:227] PREPARE: Finished. 0716 23:58:44.241349 (+ 24us) write_op.cc:237] Start() 0716 23:58:44.241351 (+ 2us) write_op.cc:242] Timestamp: P: 1689551924241331 usec, L: 0 0716 23:58:44.241351 (+ 0us) op_driver.cc:317] REPLICATION: Starting. 0716 23:58:44.241403 (+ 52us) log.cc:834] Serialized 3904 byte log entry 0716 23:58:44.242207 (+ 804us) op_driver.cc:430] REPLICATION: Finished. 0716 23:58:44.242222 (+ 15us) write_op.cc:266] APPLY: Starting. 0717 00:13:03.171012 (+858928790us) tablet_metrics.cc:481] ProbeStats: bloom_lookups=5,key_file_lookups=0,delta_file_lookups=0,mrs_lookups=0 0717 00:13:03.171024 (+ 12us) write_op.cc:277] APPLY: Finished. 0717 00:13:03.171062 (+ 38us) log.cc:834] Serialized 27 byte log entry 0717 00:13:03.171083 (+ 21us) write_op.cc:440] Releasing partition, row and schema locks 0717 00:13:03.171103 (+ 20us) write_op.cc:405] Released schema lock 0717 00:13:03.171104 (+ 1us) write_op.cc:301] FINISH: Updating metrics. Change-Id: I9628a098f3bd01cb5854998829d159036c708103 --- M src/kudu/tablet/ops/op_driver.cc M src/kudu/tablet/ops/participant_op.cc M src/kudu/tablet/ops/write_op.cc M src/kudu/tablet/tablet.cc 4 files changed, 24 insertions(+), 18 deletions(-) git pull ssh://gerrit.cloudera.org:29418/kudu refs/changes/32/20232/1 -- To view, visit http://gerrit.cloudera.org:8080/20232 To unsubscribe, visit http://gerrit.cloudera.org:8080/settings Gerrit-Project: kudu Gerrit-Branch: master Gerrit-MessageType: newchange Gerrit-Change-Id: I9628a098f3bd01cb5854998829d159036c708103 Gerrit-Change-Number: 20232 Gerrit-PatchSet: 1 Gerrit-Owner: Alexey Serbin <ale...@apache.org>
