unsigned int overflow/underflow when calculating bluestore and prepare latency

[nishant-dash]

I have some sample data [0] that shows overflow in bluestore lat, and prepare.

These seem to come from

cephtrace/src/osdtrace.cc

Lines 685 to 694 in b600246

	//bluestore level
	op.aio_size = val->aio_size;
	op.bs_prepare_lat = (val->aio_submit_stamp - val->queue_transaction_stamp)/1000;
	op.bs_aio_wait_lat = (val->aio_done_stamp - val->aio_submit_stamp)/1000;
	op.bs_pg_seq_lat = (val->kv_submit_stamp - val->aio_done_stamp)/1000;
	op.bs_kv_commit_lat = (val->kv_committed_stamp - val->kv_submit_stamp)/1000;
	if (op.wb > 0)
	op.bs_lat = (val->kv_committed_stamp - val->queue_transaction_stamp)/1000;
	else if (op.rb > 0)
	op.bs_lat = (val->reply_stamp - val->execute_ctx_stamp)/1000;

In both calculations (for bluestore latency when wb > 0) val->queue_transaction_stamp is subtracted from respective quantities. Is there something unexpected about this queue_transaction_stamp? Notice that every other bluestore field is 0 so is there something inherently messed up about the entire op data?

1. Handle some of these overflows
2. In doing 1, output queue transaction stamp as part of the trace? and set all bluestore latencies to 0?

[0]

# ./tools/analyze_osdtrace_output.py ~/osdtrace_osd.22.out -s -f bluestore_lat | grep subop_w | tail -50 | column -t
osd  22  pg  24.404  op  subop_w  size  17067    client  237508987  tid  445072     throttle_lat  1  recv_lat  28    dispatch_lat  10  queue_lat  53      osd_lat  928  peers  []  bluestore_lat  522206             (prepare  513066             aio_wait  232   aio_size  2   seq_wait  15   kv_commit  8892)    lat_type  subop_lat  lat  524717
osd  22  pg  24.2ee  op  subop_w  size  4779     client  228048575  tid  37935112   throttle_lat  0  recv_lat  14    dispatch_lat  5   queue_lat  36      osd_lat  62   peers  []  bluestore_lat  576100             (prepare  567038             aio_wait  185   aio_size  1   seq_wait  9    kv_commit  8867)    lat_type  subop_lat  lat  576247
osd  22  pg  24.f    op  subop_w  size  4779     client  186383378  tid  549722655  throttle_lat  0  recv_lat  11    dispatch_lat  7   queue_lat  25      osd_lat  68   peers  []  bluestore_lat  577410             (prepare  132                aio_wait  440   aio_size  1   seq_wait  7    kv_commit  576830)  lat_type  subop_lat  lat  581243
osd  22  pg  24.38f  op  subop_w  size  3932843  client  202845140  tid  31664836   throttle_lat  0  recv_lat  2345  dispatch_lat  7   queue_lat  29      osd_lat  38   peers  []  bluestore_lat  584666             (prepare  1726               aio_wait  2719  aio_size  73  seq_wait  115  kv_commit  580104)  lat_type  subop_lat  lat  587255
osd  22  pg  24.684  op  subop_w  size  4779     client  175806659  tid  142497069  throttle_lat  1  recv_lat  14    dispatch_lat  9   queue_lat  150129  osd_lat  35   peers  []  bluestore_lat  18414938140754960  (prepare  18414938140754960  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  169373
osd  22  pg  24.7cc  op  subop_w  size  4779     client  175044042  tid  58966757   throttle_lat  0  recv_lat  9     dispatch_lat  8   queue_lat  104671  osd_lat  40   peers  []  bluestore_lat  18414938140754964  (prepare  18414938140754964  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  123902
osd  22  pg  24.218  op  subop_w  size  12971    client  175043462  tid  128551961  throttle_lat  0  recv_lat  17    dispatch_lat  4   queue_lat  316348  osd_lat  39   peers  []  bluestore_lat  18414938140755077  (prepare  18414938140755077  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  335578
osd  22  pg  24.684  op  subop_w  size  4779     client  175806659  tid  142497068  throttle_lat  0  recv_lat  21    dispatch_lat  7   queue_lat  146630  osd_lat  27   peers  []  bluestore_lat  18414938140758676  (prepare  18414938140758676  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  169248
osd  22  pg  24.218  op  subop_w  size  8875     client  175043462  tid  128551960  throttle_lat  1  recv_lat  23    dispatch_lat  58  queue_lat  312712  osd_lat  29   peers  []  bluestore_lat  18414938140758762  (prepare  18414938140758762  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  335509
osd  22  pg  24.684  op  subop_w  size  4779     client  175806659  tid  142497067  throttle_lat  0  recv_lat  11    dispatch_lat  8   queue_lat  146635  osd_lat  29   peers  []  bluestore_lat  18414938140758805  (prepare  18414938140758805  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  168892
osd  22  pg  24.218  op  subop_w  size  17067    client  175043462  tid  128551959  throttle_lat  0  recv_lat  14    dispatch_lat  2   queue_lat  312969  osd_lat  36   peers  []  bluestore_lat  18414938140758912  (prepare  18414938140758912  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  335320
osd  22  pg  24.684  op  subop_w  size  4779     client  175806659  tid  142497066  throttle_lat  0  recv_lat  10    dispatch_lat  6   queue_lat  146716  osd_lat  18   peers  []  bluestore_lat  18414938140758926  (prepare  18414938140758926  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  169007
osd  22  pg  24.684  op  subop_w  size  4779     client  175806659  tid  142497065  throttle_lat  0  recv_lat  13    dispatch_lat  9   queue_lat  146782  osd_lat  27   peers  []  bluestore_lat  18414938140758994  (prepare  18414938140758994  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  169049
osd  22  pg  24.218  op  subop_w  size  4779     client  175043462  tid  128551958  throttle_lat  0  recv_lat  13    dispatch_lat  3   queue_lat  312876  osd_lat  27   peers  []  bluestore_lat  18414938140759034  (prepare  18414938140759034  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  335276
osd  22  pg  24.684  op  subop_w  size  4779     client  175806659  tid  142497062  throttle_lat  2  recv_lat  34    dispatch_lat  29  queue_lat  153664  osd_lat  24   peers  []  bluestore_lat  18414938140759101  (prepare  18414938140759101  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  176063
osd  22  pg  24.218  op  subop_w  size  8875     client  175043462  tid  128551957  throttle_lat  0  recv_lat  402   dispatch_lat  8   queue_lat  312755  osd_lat  37   peers  []  bluestore_lat  18414938140759167  (prepare  18414938140759167  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  335679
osd  22  pg  24.41c  op  subop_w  size  8875     client  234312331  tid  3330336    throttle_lat  2  recv_lat  28    dispatch_lat  18  queue_lat  190045  osd_lat  28   peers  []  bluestore_lat  18414938140759240  (prepare  18414938140759240  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  212618
osd  22  pg  24.684  op  subop_w  size  17067    client  237440052  tid  4385400    throttle_lat  0  recv_lat  33    dispatch_lat  8   queue_lat  219893  osd_lat  32   peers  []  bluestore_lat  18414938140759382  (prepare  18414938140759382  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  242524
osd  22  pg  24.218  op  subop_w  size  17067    client  175043462  tid  128551956  throttle_lat  0  recv_lat  13    dispatch_lat  3   queue_lat  312861  osd_lat  33   peers  []  bluestore_lat  18414938140759532  (prepare  18414938140759532  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  335727
osd  22  pg  24.404  op  subop_w  size  4779     client  204309844  tid  41013202   throttle_lat  1  recv_lat  28    dispatch_lat  26  queue_lat  220007  osd_lat  28   peers  []  bluestore_lat  18414938140759600  (prepare  18414938140759600  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  243034
osd  22  pg  24.504  op  subop_w  size  78507    client  229590750  tid  46703677   throttle_lat  1  recv_lat  53    dispatch_lat  66  queue_lat  242855  osd_lat  31   peers  []  bluestore_lat  18414938140759610  (prepare  18414938140759610  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  265853
osd  22  pg  24.218  op  subop_w  size  12971    client  175043462  tid  128551955  throttle_lat  0  recv_lat  19    dispatch_lat  4   queue_lat  312959  osd_lat  34   peers  []  bluestore_lat  18414938140759638  (prepare  18414938140759638  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  335675
osd  22  pg  24.684  op  subop_w  size  4779     client  175806659  tid  142497061  throttle_lat  0  recv_lat  10    dispatch_lat  7   queue_lat  248871  osd_lat  26   peers  []  bluestore_lat  18414938140759693  (prepare  18414938140759693  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  271768
osd  22  pg  24.218  op  subop_w  size  33451    client  175043462  tid  128551954  throttle_lat  0  recv_lat  28    dispatch_lat  9   queue_lat  312927  osd_lat  32   peers  []  bluestore_lat  18414938140759807  (prepare  18414938140759807  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  331969
osd  22  pg  24.65c  op  subop_w  size  17067    client  199126745  tid  231581725  throttle_lat  0  recv_lat  14    dispatch_lat  8   queue_lat  248967  osd_lat  44   peers  []  bluestore_lat  18414938140759815  (prepare  18414938140759815  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  272539
osd  22  pg  24.684  op  subop_w  size  4779     client  175806659  tid  142497060  throttle_lat  0  recv_lat  6     dispatch_lat  7   queue_lat  248884  osd_lat  38   peers  []  bluestore_lat  18414938140759833  (prepare  18414938140759833  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  271897
osd  22  pg  24.218  op  subop_w  size  4779     client  175043462  tid  128551953  throttle_lat  0  recv_lat  9     dispatch_lat  5   queue_lat  313026  osd_lat  34   peers  []  bluestore_lat  18414938140759929  (prepare  18414938140759929  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  332153
osd  22  pg  24.218  op  subop_w  size  4779     client  175043462  tid  128551952  throttle_lat  1  recv_lat  13    dispatch_lat  6   queue_lat  313016  osd_lat  36   peers  []  bluestore_lat  18414938140760091  (prepare  18414938140760091  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  332286
osd  22  pg  24.218  op  subop_w  size  8875     client  175043462  tid  128551951  throttle_lat  1  recv_lat  47    dispatch_lat  6   queue_lat  335872  osd_lat  23   peers  []  bluestore_lat  18414938140760220  (prepare  18414938140760220  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  354988
osd  22  pg  24.307  op  subop_w  size  4779     client  205751599  tid  149073115  throttle_lat  1  recv_lat  17    dispatch_lat  13  queue_lat  119543  osd_lat  35   peers  []  bluestore_lat  18414938140760244  (prepare  18414938140760244  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  138897
osd  22  pg  24.347  op  subop_w  size  4779     client  216066033  tid  18978483   throttle_lat  0  recv_lat  24    dispatch_lat  10  queue_lat  132884  osd_lat  27   peers  []  bluestore_lat  18414938140760256  (prepare  18414938140760256  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  152270
osd  22  pg  24.347  op  subop_w  size  4779     client  216066033  tid  18978369   throttle_lat  2  recv_lat  25    dispatch_lat  17  queue_lat  144017  osd_lat  25   peers  []  bluestore_lat  18414938140760367  (prepare  18414938140760367  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  163458
osd  22  pg  24.218  op  subop_w  size  4779     client  175043462  tid  128551949  throttle_lat  0  recv_lat  8     dispatch_lat  4   queue_lat  397309  osd_lat  50   peers  []  bluestore_lat  18414938140760372  (prepare  18414938140760372  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  416479
osd  22  pg  24.e7   op  subop_w  size  4779     client  181754238  tid  50158111   throttle_lat  1  recv_lat  17    dispatch_lat  11  queue_lat  150151  osd_lat  38   peers  []  bluestore_lat  18414938140760388  (prepare  18414938140760388  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  169594
osd  22  pg  24.5f8  op  subop_w  size  4779     client  220619212  tid  42660012   throttle_lat  1  recv_lat  17    dispatch_lat  7   queue_lat  349143  osd_lat  32   peers  []  bluestore_lat  18414938140760400  (prepare  18414938140760400  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  368241
osd  22  pg  24.4f7  op  subop_w  size  4779     client  214169350  tid  84712182   throttle_lat  1  recv_lat  17    dispatch_lat  13  queue_lat  162128  osd_lat  23   peers  []  bluestore_lat  18414938140760460  (prepare  18414938140760460  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  181665
osd  22  pg  24.317  op  subop_w  size  4779     client  235097157  tid  21429324   throttle_lat  1  recv_lat  18    dispatch_lat  15  queue_lat  244032  osd_lat  41   peers  []  bluestore_lat  18414938140760556  (prepare  18414938140760556  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  263634
osd  22  pg  24.218  op  subop_w  size  4779     client  175043462  tid  128551948  throttle_lat  0  recv_lat  13    dispatch_lat  9   queue_lat  397272  osd_lat  30   peers  []  bluestore_lat  18414938140760576  (prepare  18414938140760576  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  416604
osd  22  pg  24.407  op  subop_w  size  4779     client  220619212  tid  42660018   throttle_lat  0  recv_lat  21    dispatch_lat  11  queue_lat  244968  osd_lat  51   peers  []  bluestore_lat  18414938140760606  (prepare  18414938140760606  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  264611
osd  22  pg  24.47   op  subop_w  size  4779     client  228983548  tid  10812078   throttle_lat  1  recv_lat  16    dispatch_lat  14  queue_lat  268984  osd_lat  35   peers  []  bluestore_lat  18414938140760753  (prepare  18414938140760753  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  288736
osd  22  pg  24.782  op  subop_w  size  4779     client  209371935  tid  26366886   throttle_lat  0  recv_lat  8     dispatch_lat  10  queue_lat  178163  osd_lat  41   peers  []  bluestore_lat  18414938140760794  (prepare  18414938140760794  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  197183
osd  22  pg  24.4f7  op  subop_w  size  4779     client  199065857  tid  15688306   throttle_lat  0  recv_lat  16    dispatch_lat  10  queue_lat  271529  osd_lat  28   peers  []  bluestore_lat  18414938140760806  (prepare  18414938140760806  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  291295
osd  22  pg  24.782  op  subop_w  size  4779     client  209371935  tid  26366885   throttle_lat  0  recv_lat  17    dispatch_lat  7   queue_lat  178253  osd_lat  33   peers  []  bluestore_lat  18414938140760923  (prepare  18414938140760923  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  197386
osd  22  pg  24.347  op  subop_w  size  4779     client  237202374  tid  2641769    throttle_lat  0  recv_lat  6     dispatch_lat  4   queue_lat  363433  osd_lat  33   peers  []  bluestore_lat  18414938140760928  (prepare  18414938140760928  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  383006
osd  22  pg  24.277  op  subop_w  size  21163    client  175042552  tid  26338273   throttle_lat  1  recv_lat  58    dispatch_lat  8   queue_lat  338743  osd_lat  30   peers  []  bluestore_lat  18414938140760940  (prepare  18414938140760940  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  357360
osd  22  pg  24.218  op  subop_w  size  4779     client  175043462  tid  128551947  throttle_lat  0  recv_lat  6     dispatch_lat  2   queue_lat  397041  osd_lat  28   peers  []  bluestore_lat  18414938140761047  (prepare  18414938140761047  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  416717
osd  22  pg  24.347  op  subop_w  size  17067    client  237202374  tid  2641768    throttle_lat  0  recv_lat  92    dispatch_lat  4   queue_lat  363392  osd_lat  19   peers  []  bluestore_lat  18414938140761057  (prepare  18414938140761057  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  382549
osd  22  pg  24.782  op  subop_w  size  4779     client  209371935  tid  26366884   throttle_lat  2  recv_lat  27    dispatch_lat  20  queue_lat  178149  osd_lat  35   peers  []  bluestore_lat  18414938140761110  (prepare  18414938140761110  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  197471
osd  22  pg  24.4e1  op  subop_w  size  679      client  211544509  tid  26653493   throttle_lat  2  recv_lat  16    dispatch_lat  17  queue_lat  248986  osd_lat  50   peers  []  bluestore_lat  18414938140761124  (prepare  18414938140761124  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  268120
osd  22  pg  24.65c  op  subop_w  size  4195131  client  207590839  tid  73040359   throttle_lat  1  recv_lat  2376  dispatch_lat  21  queue_lat  336666  osd_lat  33   peers  []  bluestore_lat  18414938140762907  (prepare  18414938140762907  aio_wait  0     aio_size  0   seq_wait  0    kv_commit  0)       lat_type  subop_lat  lat  365565

[nishant-dash]

I have uploaded the trace here osdtrace_osd.22.log

[nishant-dash]

@taodd Actually thinking further, since all bluestore fields are 0, it could be that aio_submit_stamp and kv_committed_stamp are both 0 and queue_transaction_stamp is non-zero.
That would explain why 2 different subtractions give the same underflow value

[nishant-dash]

im extremely new to bpf stuff but is what we are seeing happening because in

cephtrace/src/osdtrace.bpf.c

Lines 531 to 552 in b600246

	if (state == 0) { // STATE_PREPARE
	vp->aio_submit_stamp = bpf_ktime_get_boot_ns();
	__u64 pending_addr = fetch_var_member_addr(v, vf);
	int pending_num = 0;
	bpf_probe_read_user(&pending_num, sizeof(pending_num), (void *)pending_addr);
	vp->aio_size = pending_num;
	if (pending_num == 0)
	vp->aio_done_stamp = vp->aio_submit_stamp;
	bpf_printk("uprobe_txc_state_proc owner %lld tid %lld aio_submit_stamp = %lld", key->owner, key->tid, vp->aio_submit_stamp);
	} else if (state == 1) { // STATE_AIO_WAIT
	// until flushed can it be considered committed, not here.
	vp->aio_done_stamp = bpf_ktime_get_boot_ns();
	bpf_printk("uprobe_txc_state_proc owner %lld tid %lld aio_done_stamp = %lld", key->owner, key->tid, vp->aio_done_stamp);
	} else if (state == 2) { // STATE_IO_DONE sending to kv queue
	vp->kv_submit_stamp = bpf_ktime_get_boot_ns();
	bpf_printk("uprobe_txc_state_proc owner %lld tid %lld kv_submit_stamp = %lld", key->owner, key->tid, vp->kv_submit_stamp);
	} else if (state == 4) { // STATE_KV_SUBMITTED
	vp->kv_committed_stamp = bpf_ktime_get_boot_ns();
	bpf_printk("uprobe_txc_state_proc owner %lld tid %lld kv_committed_stamp = %lld", key->owner, key->tid, vp->kv_committed_stamp);
	// last stage of the ctx, delete it from the map
	bpf_map_delete_elem(&ctx_opk, &ck);
	}

is txc_state_proc not being called? or the call to it is messed up?

In any case I think we can add some high level checks to emit the trace line if aio_submit_stamp is 0 (and output a different trype of trace that highlights what is actually going on)? emitting a line with 0 might skew the percentiles

[taodd]

im extremely new to bpf stuff but is what we are seeing happening because in

cephtrace/src/osdtrace.bpf.c

Lines 531 to 552 in b600246

if (state == 0) { // STATE_PREPARE
vp->aio_submit_stamp = bpf_ktime_get_boot_ns();
__u64 pending_addr = fetch_var_member_addr(v, vf);
int pending_num = 0;
bpf_probe_read_user(&pending_num, sizeof(pending_num), (void *)pending_addr);
vp->aio_size = pending_num;
if (pending_num == 0)
vp->aio_done_stamp = vp->aio_submit_stamp;
bpf_printk("uprobe_txc_state_proc owner %lld tid %lld aio_submit_stamp = %lld", key->owner, key->tid, vp->aio_submit_stamp);
} else if (state == 1) { // STATE_AIO_WAIT
// until flushed can it be considered committed, not here.
vp->aio_done_stamp = bpf_ktime_get_boot_ns();
bpf_printk("uprobe_txc_state_proc owner %lld tid %lld aio_done_stamp = %lld", key->owner, key->tid, vp->aio_done_stamp);
} else if (state == 2) { // STATE_IO_DONE sending to kv queue
vp->kv_submit_stamp = bpf_ktime_get_boot_ns();
bpf_printk("uprobe_txc_state_proc owner %lld tid %lld kv_submit_stamp = %lld", key->owner, key->tid, vp->kv_submit_stamp);
} else if (state == 4) { // STATE_KV_SUBMITTED
vp->kv_committed_stamp = bpf_ktime_get_boot_ns();
bpf_printk("uprobe_txc_state_proc owner %lld tid %lld kv_committed_stamp = %lld", key->owner, key->tid, vp->kv_committed_stamp);
// last stage of the ctx, delete it from the map
bpf_map_delete_elem(&ctx_opk, &ck);
}
is txc_state_proc not being called? or the call to it is messed up?

In any case I think we can add some high level checks to emit the trace line if aio_submit_stamp is 0 (and output a different trype of trace that highlights what is actually going on)? emitting a line with 0 might skew the percentiles

Yes, I think you are right, it seems txc_state_proc isn't being called at all, or the state of the transaction had jumped directly to the end. Let me check how can that be possible.

[pponnuvel]

Is this reproducible? I've some theories too but it would be very helpful if there's a way to test/reproduce.