search

datafuselabs / databend

𝗗𝗮𝘁𝗮, 𝗔𝗻𝗮𝗹𝘆𝘁𝗶𝗰𝘀 & 𝗔𝗜. Modern alternative to Snowflake. Cost-effective and simple for massive-scale analytics. https://databend.com
https://docs.databend.com
Other
7.31k stars 704 forks source link

chore(meta): tracking query id for meta log #15497

Closed zhang2014 closed 2 weeks ago

zhang2014 commented 2 weeks ago

I hereby agree to the terms of the CLA available at: https://docs.databend.com/dev/policies/cla/

Summary

chore(meta): tracking query id for meta log

Tests

Type of change

This change is Reviewable

zhang2014 commented 2 weeks ago

meta server side log

{"timestamp":"2024-05-13T07:01:34.374359Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"handle(MetaGrpcReadReq)","req":"ForwardRequest { forward_to_leader: 1, body: MGetKV(MGetKVReq { keys: [\"__fd_table/1/t1\"] }) }"}}
{"timestamp":"2024-05-13T07:01:34.374388Z","level":"INFO","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"Elapsed: total: 66.792µs, busy: 66.541µs; ReadRequest: ForwardRequest { forward_to_leader: 1, body: MGetKV(MGetKVReq { keys: [\"__fd_table/1/t1\"] }) }"}}
{"timestamp":"2024-05-13T07:01:34.377285Z","level":"INFO","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"handle_kv_read_v1: Received ReadRequest: MGetKV(MGetKVReq { keys: [\"__fd_table_by_id/27039\"] })"}}
{"timestamp":"2024-05-13T07:01:34.377561Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"handle_forwardable_request","target":"1","req":"ForwardRequest { forward_to_leader: 1, body: MGetKV(MGetKVReq { keys: [\"__fd_table_by_id/27039\"] }) }"}}
{"timestamp":"2024-05-13T07:01:34.377617Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"curr_leader_id: Some(0)"}}
{"timestamp":"2024-05-13T07:01:34.377689Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"assume_leader: is_err: false"}}
{"timestamp":"2024-05-13T07:01:34.377727Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"handle(MetaGrpcReadReq)","req":"ForwardRequest { forward_to_leader: 1, body: MGetKV(MGetKVReq { keys: [\"__fd_table_by_id/27039\"] }) }"}}
{"timestamp":"2024-05-13T07:01:34.377768Z","level":"INFO","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"Elapsed: total: 237.459µs, busy: 237.083µs; ReadRequest: ForwardRequest { forward_to_leader: 1, body: MGetKV(MGetKVReq { keys: [\"__fd_table_by_id/27039\"] }) }"}}
{"timestamp":"2024-05-13T07:01:34.381055Z","level":"INFO","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"handle_kv_read_v1: Received ReadRequest: MGetKV(MGetKVReq { keys: [\"__fd_object_owners/test_tenant/table-by-id/27039\"] })"}}
{"timestamp":"2024-05-13T07:01:34.381152Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"handle_forwardable_request","target":"1","req":"ForwardRequest { forward_to_leader: 1, body: MGetKV(MGetKVReq { keys: [\"__fd_object_owners/test_tenant/table-by-id/27039\"] }) }"}}
{"timestamp":"2024-05-13T07:01:34.381169Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"curr_leader_id: Some(0)"}}
{"timestamp":"2024-05-13T07:01:34.381175Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"assume_leader: is_err: false"}}
{"timestamp":"2024-05-13T07:01:34.381186Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"handle(MetaGrpcReadReq)","req":"ForwardRequest { forward_to_leader: 1, body: MGetKV(MGetKVReq { keys: [\"__fd_object_owners/test_tenant/table-by-id/27039\"] }) }"}}
{"timestamp":"2024-05-13T07:01:34.381218Z","level":"INFO","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"Elapsed: total: 73.708µs, busy: 73.625µs; ReadRequest: ForwardRequest { forward_to_leader: 1, body: MGetKV(MGetKVReq { keys: [\"__fd_object_owners/test_tenant/table-by-id/27039\"] }) }"}}
{"timestamp":"2024-05-13T07:01:36.512818Z","level":"INFO","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"handle_kv_read_v1: Received ReadRequest: ListKV(ListKVReq { prefix: \"__fd_settings/test_tenant/\" })"}}
{"timestamp":"2024-05-13T07:01:36.512915Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"handle_forwardable_request","target":"1","req":"ForwardRequest { forward_to_leader: 1, body: ListKV(ListKVReq { prefix: \"__fd_settings/test_tenant/\" }) }"}}
{"timestamp":"2024-05-13T07:01:36.512937Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"curr_leader_id: Some(0)"}}
{"timestamp":"2024-05-13T07:01:36.512945Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"assume_leader: is_err: false"}}
{"timestamp":"2024-05-13T07:01:36.512955Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"handle(MetaGrpcReadReq)","req":"ForwardRequest { forward_to_leader: 1, body: ListKV(ListKVReq { prefix: \"__fd_settings/test_tenant/\" }) }"}}
{"timestamp":"2024-05-13T07:01:36.513023Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"list_kv() took 52.333µs"}}
{"timestamp":"2024-05-13T07:01:36.513049Z","level":"INFO","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"Elapsed: total: 143.625µs, busy: 143.333µs; ReadRequest: ForwardRequest { forward_to_leader: 1, body: ListKV(ListKVReq { prefix: \"__fd_settings/test_tenant/\" }) }"}}
{"timestamp":"2024-05-13T07:01:36.514529Z","level":"INFO","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"handle_kv_read_v1: Received ReadRequest: ListKV(ListKVReq { prefix: \"__fd_clusters/test_tenant/test_cluster/databend_query\" })"}}
{"timestamp":"2024-05-13T07:01:36.514611Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"handle_forwardable_request","target":"1","req":"ForwardRequest { forward_to_leader: 1, body: ListKV(ListKVReq { prefix: \"__fd_clusters/test_tenant/test_cluster/databend_query\" }) }"}}
{"timestamp":"2024-05-13T07:01:36.514635Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"curr_leader_id: Some(0)"}}
{"timestamp":"2024-05-13T07:01:36.514648Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"assume_leader: is_err: false"}}
{"timestamp":"2024-05-13T07:01:36.514659Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"handle(MetaGrpcReadReq)","req":"ForwardRequest { forward_to_leader: 1, body: ListKV(ListKVReq { prefix: \"__fd_clusters/test_tenant/test_cluster/databend_query\" }) }"}}
{"timestamp":"2024-05-13T07:01:36.514724Z","level":"DEBUG","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"list_kv() took 51.375µs"}}
{"timestamp":"2024-05-13T07:01:36.514746Z","level":"INFO","query_id":"107c0ae8-3175-47da-b19a-a789c1c1c6ab","fields":{"message":"Elapsed: total: 142.583µs, busy: 142.416µs; ReadRequest: ForwardRequest { forward_to_leader: 1, body: ListKV(ListKVReq { prefix: \"__fd_clusters/test_tenant/test_cluster/databend_query\" }) }"}}

query side meta client log(not same query):

483343d1-777b-4067-9a90-525c3ee40510 2024-05-13T07:09:09.986663Z DEBUG databend_common_meta_client::grpc_client: grpc_client.rs:1050 MetaGrpcClient::kv_read_v1 result, 0-th try result=Ok(Response { metadata: MetadataMap { headers: {"content-type": "application/grpc", "date": "Mon, 13 May 2024 07:09:09 GMT"} }, message: Streaming, extensions: Extensions })
483343d1-777b-4067-9a90-525c3ee40510 2024-05-13T07:09:09.986688Z DEBUG databend_common_meta_client::grpc_client: grpc_client.rs:582 MetaGrpcClient send response to the handle request_id=101 resp=StreamMGet(Ok("<stream>"))
483343d1-777b-4067-9a90-525c3ee40510 2024-05-13T07:09:09.986788Z DEBUG databend_common_meta_client::grpc_client: grpc_client.rs:266 Meta ClientHandle send request to meta client worker request=ClientWorkerRequest { request_id: 102, req: StreamMGet(Streamed(MGetKVReq { keys: ["__fd_database_by_id/1"] })) }
483343d1-777b-4067-9a90-525c3ee40510 2024-05-13T07:09:09.986827Z DEBUG databend_common_meta_client::grpc_client: grpc_client.rs:474 MetaGrpcClient worker handle request worker_request=ClientWorkerRequest { request_id: 102, req: StreamMGet(Streamed(MGetKVReq { keys: ["__fd_database_by_id/1"] })) }
483343d1-777b-4067-9a90-525c3ee40510 2024-05-13T07:09:09.986856Z DEBUG databend_common_meta_client::grpc_client: grpc_client.rs:1029 MetaGrpcClient::kv_read_v1 request req=MGetKV(MGetKVReq { keys: ["__fd_database_by_id/1"] })
483343d1-777b-4067-9a90-525c3ee40510 2024-05-13T07:09:09.986866Z DEBUG databend_common_meta_client::grpc_client: grpc_client.rs:650 meta-service endpoints: current:Some("0.0.0.0:9191"), all:[0.0.0.0:9191]
483343d1-777b-4067-9a90-525c3ee40510 2024-05-13T07:09:09.986870Z DEBUG databend_common_meta_client::grpc_client: grpc_client.rs:660 get or build ReadClient to 0.0.0.0:9191
483343d1-777b-4067-9a90-525c3ee40510 2024-05-13T07:09:09.986883Z DEBUG databend_common_base::containers::pool: pool.rs:130 check reused item res: Ok(EstablishedClient { client: MetaServiceClient { inner: Grpc { inner: InterceptedService { inner: Channel, f: databend_common_meta_client::grpc_client::AuthInterceptor }, origin: /, compression_encoding: None, accept_compression_encodings: EnabledCompressionEncodings, max_decoding_message_size: Some(16777216), max_encoding_message_size: Some(16777216) } }, server_protocol_version: 1002413, target_endpoint: "0.0.0.0:9191", endpoints: Mutex { data: Endpoints { current: Some("0.0.0.0:9191"), nodes: {"0.0.0.0:9191": Status} } }, error: Mutex { data: None } })
483343d1-777b-4067-9a90-525c3ee40510 2024-05-13T07:09:09.986901Z DEBUG databend_common_meta_client::grpc_action: grpc_action.rs:145 build raft_request req=RaftRequest { data: "{\"MGetKV\":{\"keys\":[\"__fd_database_by_id/1\"]}}" }