20230202_zeroed_startevent_of_historic_op.md

20230202_zeroed_startevent_of_historic_op.md

The zeroed StartEvent problem

After running some client IO:

[rzarzynski@o06 build]$ bin/ceph tell osd.2 dump_historic_slow_ops
...
            {
                "type": "client_request",
                "id": 216614,
                "detail": {
                    "time_event": {
                        "name": "crimson::osd::TrackableOperationT<crimson::osd::ClientRequest>::StartEvent",                                                                                                     
                        "initiated_at": "0.000000"
                    },
                    "blocking_event": {
                        "name": "crimson::osd::ConnectionPipeline::AwaitActive",
                        "initiated_at": "2023-02-02T01:08:59.502627+0000"
                    },
                    "blocking_event": {
                        "name": "crimson::osd::ConnectionPipeline::AwaitMap",
                        "initiated_at": "2023-02-02T01:08:59.502658+0000"
                    },
                    "blocking_event": {
                        "name": "crimson::osd::OSDMapGate<(crimson::osd::OSDMapGateType)0>::OSDMapBlocker",                                                                                                       
                        "initiated_at": "0.000000"
                    },
                    "blocking_event": {
                        "name": "crimson::osd::ConnectionPipeline::GetPG",
                        "initiated_at": "2023-02-02T01:08:59.502683+0000"
                    },
                    "blocking_event": {
                        "name": "crimson::osd::PGMap::PGCreationState",
                        "initiated_at": "0.000000"
                    },
                    "time_event": {
                        "name": "crimson::osd::TrackableOperationT<crimson::osd::ClientRequest>::CompletionEvent",                                                                                                
                        "initiated_at": "2023-02-02T01:08:59.502908+0000"
                    }
                }
            }
        ]
    },

• https://github.com/ceph/ceph/blob/8a095e903bc7518afbabe0818cc7a03d0f6cfe76/src/crimson/osd/osd_operations/client_request.h#L75-L83
• https://github.com/ceph/ceph/blob/main/src/crimson/osd/osd_operations/client_request.h#L96-L107

The root cause for zeroed StartEvent:

580b5e24c6ad7f9cbf36fecd4be6af2c7ad053e2 has removed the call to track_event<StartEvent>. I think the rationale was that e.g. RepRequest is not trackable to the new start_pg_operation() is shared with it as well.

diff --git a/src/crimson/osd/osd_operations/client_request.cc b/src/crimson/osd/osd_operations/client_request.cc
index 87f28a482d2..0d22fe47e35 100644
--- a/src/crimson/osd/osd_operations/client_request.cc
+++ b/src/crimson/osd/osd_operations/client_request.cc
@@ -55,7 +55,9 @@ ClientRequest::ClientRequest(
     conn(std::move(conn)),
     m(std::move(m)),
     instance_handle(new instance_handle_t)
-{}
+{
+  track_event<StartEvent>();
+}
 
 ClientRequest::~ClientRequest()
 {

Fix PR: ceph/ceph#50019.