You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues-all@impala.apache.org by "ASF subversion and git services (Jira)" <ji...@apache.org> on 2023/06/24 12:27:00 UTC
[jira] [Commented] (IMPALA-6665) Tag CatalogOp logs with query IDs
[ https://issues.apache.org/jira/browse/IMPALA-6665?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17736714#comment-17736714 ]
ASF subversion and git services commented on IMPALA-6665:
---------------------------------------------------------
Commit 715af9af42e86a3a1f31061ed2d41ed425accd0e in impala's branch refs/heads/master from stiga-huang
[ https://gitbox.apache.org/repos/asf?p=impala.git;h=715af9af4 ]
IMPALA-6665: Tag CatalogOp logs with query ids
Adds query id in TCatalogServiceRequestHeader. Coordinator uses it to
pass the query id in catalogd RPCs. The query id is then used in
catalogd to be set in the ThreadDebugInfo. It will be prepended to logs
of the thread executing the RPC.
Note that prepending the query id got from the thread local
ThreadDebugInfo is an existing mechanism already used in coordinator.
All log levels will be affected.
Here is an example of a CTAS command. It actually contains two RPCs,
an execDdl and an updateCatalog request. The query id binds them
together.
I0524 22:16:58.439786 17112 JniUtil.java:166] 5043cba7eaa92133:600815f800000000] execDdl request: CREATE_TABLE_AS_SELECT test_generic_java_udfs_ea877ad4.replace_string_input issued by jenkins
I0524 22:16:58.450062 17112 Table.java:221] 5043cba7eaa92133:600815f800000000] createEventId_ for table: test_generic_java_udfs_ea877ad4.replace_string_input set to: 41893
I0524 22:16:58.450099 17112 Table.java:236] 5043cba7eaa92133:600815f800000000] lastSyncedEventId_ for table: test_generic_java_udfs_ea877ad4.replace_string_input set from -1 to 41893
I0524 22:16:58.450129 17112 CatalogOpExecutor.java:3607] 5043cba7eaa92133:600815f800000000] Created catalog table test_generic_java_udfs_ea877ad4.replace_string_input with create event id 41893
I0524 22:16:58.450171 17112 JniUtil.java:177] 5043cba7eaa92133:600815f800000000] Finished execDdl request: CREATE_TABLE_AS_SELECT test_generic_java_udfs_ea877ad4.replace_string_input issued by jenkins. Time spent: 11ms
I0524 22:16:58.469336 8057 JniUtil.java:166] 5043cba7eaa92133:600815f800000000] updateCatalog request: Update catalog for test_generic_java_udfs_ea877ad4.replace_string_input
I0524 22:16:58.469403 8057 TableLoadingMgr.java:72] 5043cba7eaa92133:600815f800000000] Loading metadata for table: test_generic_java_udfs_ea877ad4.replace_string_input
I0524 22:16:58.469463 12091 TableLoader.java:76] Loading metadata for: test_generic_java_udfs_ea877ad4.replace_string_input (Load for INSERT)
I0524 22:16:58.469496 8057 TableLoadingMgr.java:74] 5043cba7eaa92133:600815f800000000] Remaining items in queue: 0. Loads in progress: 1
I0524 22:16:58.473240 12091 Table.java:221] createEventId_ for table: test_generic_java_udfs_ea877ad4.replace_string_input set to: 41893
I0524 22:16:58.473273 12091 Table.java:236] lastSyncedEventId_ for table: test_generic_java_udfs_ea877ad4.replace_string_input set from -1 to 41893
I0524 22:16:58.473307 12091 HdfsTable.java:1243] Loading metadata for table definition and all partition(s) of test_generic_java_udfs_ea877ad4.replace_string_input (Load for INSERT)
I0524 22:16:58.473488 12091 HdfsTable.java:1863] Loaded 1 columns from HMS. Actual columns: 1
I0524 22:16:58.476650 12091 HdfsTable.java:3028] Load Valid Write Id List Done. Time taken: 1.545us
I0524 22:16:58.476675 12091 HdfsTable.java:1282] Fetching partition metadata from the Metastore: test_generic_java_udfs_ea877ad4.replace_string_input
I0524 22:16:58.477051 12091 MetaStoreUtil.java:190] Fetching 0 partitions for: test_generic_java_udfs_ea877ad4.replace_string_input using partition batch size: 1000
I0524 22:16:58.477066 12091 HdfsTable.java:1289] Fetched partition metadata from the Metastore: test_generic_java_udfs_ea877ad4.replace_string_input
I0524 22:16:58.477887 12091 HdfsTable.java:813] Loaded file and block metadata for test_generic_java_udfs_ea877ad4.replace_string_input partitions: . Time taken: 442.635us
I0524 22:16:58.478031 12091 Table.java:1048] last refreshed event id for table: test_generic_java_udfs_ea877ad4.replace_string_input set to: -1
I0524 22:16:58.478052 12091 TableLoader.java:176] Loaded metadata for: test_generic_java_udfs_ea877ad4.replace_string_input (8ms)
I0524 22:16:58.479095 8057 CatalogOpExecutor.java:6937] 5043cba7eaa92133:600815f800000000] 1 new files detected for table test_generic_java_udfs_ea877ad4.replace_string_input
I0524 22:16:58.479876 8057 MetastoreShim.java:476] 5043cba7eaa92133:600815f800000000] Firing 1 insert event(s) for test_generic_java_udfs_ea877ad4.replace_string_input
I0524 22:16:58.484315 8057 MetastoreShim.java:414] 5043cba7eaa92133:600815f800000000] Time taken to fire insert events on table test_generic_java_udfs_ea877ad4.replace_string_input: 4 msec
I0524 22:16:58.484354 8057 CatalogServiceCatalog.java:1126] 5043cba7eaa92133:600815f800000000] Added eventId 41894 in table's test_generic_java_udfs_ea877ad4.replace_string_input in-flight events
I0524 22:16:58.487223 8057 HdfsTable.java:1243] 5043cba7eaa92133:600815f800000000] Reloading metadata for all partition(s) of test_generic_java_udfs_ea877ad4.replace_string_input (INSERT)
I0524 22:16:58.487262 8057 HdfsTable.java:3028] 5043cba7eaa92133:600815f800000000] Load Valid Write Id List Done. Time taken: 1.506us
I0524 22:16:58.487931 8057 HdfsTable.java:813] 5043cba7eaa92133:600815f800000000] Loaded file and block metadata for test_generic_java_udfs_ea877ad4.replace_string_input partitions: . Time taken: 262.133us
I0524 22:16:58.487958 8057 HdfsTable.java:1280] 5043cba7eaa92133:600815f800000000] Incrementally loaded table metadata for: test_generic_java_udfs_ea877ad4.replace_string_input
I0524 22:16:58.488173 8057 JniUtil.java:177] 5043cba7eaa92133:600815f800000000] Finished updateCatalog request: Update catalog for test_generic_java_udfs_ea877ad4.replace_string_input. Time spent: 19ms
Note that table loading is executed asynchronizedly in other Java
threads. They are not tagged with query id yet. We can improve this in
the future.
Tests:
- Build and run tests locally
Change-Id: I90933433e23a171993de3c1ee355d776a53eda66
Reviewed-on: http://gerrit.cloudera.org:8080/19926
Reviewed-by: Impala Public Jenkins <im...@cloudera.com>
Tested-by: Impala Public Jenkins <im...@cloudera.com>
> Tag CatalogOp logs with query IDs
> ---------------------------------
>
> Key: IMPALA-6665
> URL: https://issues.apache.org/jira/browse/IMPALA-6665
> Project: IMPALA
> Issue Type: Improvement
> Components: Catalog
> Affects Versions: Impala 2.12.0
> Reporter: Bharath Vissapragada
> Assignee: Quanlong Huang
> Priority: Major
> Labels: supportability
>
> Similar to IMPALA-6664. The idea is to improve catalog server logging by adding query-ID to each of the Catalog server log statements. This helps map Catalog errors to specific queries, which is currently not possible.
> Raising a separate jira for the Catalog server since fixing it could be a little tricker than the other components since we don't have the query hash readily available in the Catalog context. We need to augment the Catalog RPCs with this data.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: issues-all-unsubscribe@impala.apache.org
For additional commands, e-mail: issues-all-help@impala.apache.org