Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 1 commit into from
May 13, 2024

Conversation

zhang2014
Copy link
Member

@zhang2014 zhang2014 commented May 13, 2024

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

  • Fixes #[Link the issue here]

Tests

  • Unit Test
  • Logic Test
  • Benchmark Test
  • No Test - common log

Type of change

  • Bug Fix (non-breaking change which fixes an issue)
  • New Feature (non-breaking change which adds functionality)
  • Breaking Change (fix or feature that could cause existing functionality not to work as expected)
  • Documentation Update
  • Refactoring
  • Performance Improvement
  • Other (please describe):chore(meta): tracking query id for meta log

This change is Reviewable

@zhang2014 zhang2014 requested review from drmingdrmer and BohuTANG May 13, 2024 07:07
@github-actions github-actions bot added the pr-chore this PR only has small changes that no need to record, like coding styles. label May 13, 2024
@zhang2014
Copy link
Member Author

zhang2014 commented May 13, 2024

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\"]}}" }

Copy link
Member

@drmingdrmer drmingdrmer left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Very useful and helpful, thank you!

@BohuTANG BohuTANG merged commit 1ff87bb into databendlabs:main May 13, 2024
75 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
pr-chore this PR only has small changes that no need to record, like coding styles.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants