[
https://issues.apache.org/jira/browse/HIVE-27773?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Ramesh Kumar Thangarajan updated HIVE-27773:
--------------------------------------------
Description:
Looking at the below logs suggest that the get_valid_write_ids is not cached
for a single query for a single table. It is being called multiple times across
different phases in the compilation of the query. We should verify if we can
safely cache and re use the results. That way we can avoid around 40-50 ms out
of 678ms compilation time.
{code:java}
2023-09-19T02:55:06,940 INFO [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] ql.Driver: Compiling
command(queryId=rameshkumar_20230919025506_b005cc57-1717-4798-b8da-b502aa7ca3d6):
2023-09-19T02:55:06,967 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2023-09-19T02:55:06,979 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
start=1695117306967 end=1695117306979 duration=12
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
error=false>
2023-09-19T02:55:06,980 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2023-09-19T02:55:06,986 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
start=1695117306980 end=1695117306986 duration=6
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
error=false>
2023-09-19T02:55:06,988 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2023-09-19T02:55:06,995 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
start=1695117306988 end=1695117306995 duration=7
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
error=false>
2023-09-19T02:55:06,997 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2023-09-19T02:55:07,007 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
start=1695117306997 end=1695117307007 duration=10
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
error=false>
2023-09-19T02:55:07,009 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2023-09-19T02:55:07,017 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
start=1695117307009 end=1695117307017 duration=8
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
error=false>
2023-09-19T02:55:07,018 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2023-09-19T02:55:07,026 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
start=1695117307018 end=1695117307026 duration=8
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
error=false>
2023-09-19T02:55:07,059 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2023-09-19T02:55:07,068 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
start=1695117307059 end=1695117307068 duration=9
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
error=false>
2023-09-19T02:55:07,618 INFO [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] ql.Driver: Completed compiling
command(queryId=rameshkumar_20230919025506_b005cc57-1717-4798-b8da-b502aa7ca3d6);
Time taken: 0.678 seconds{code}
was:
Looking at the below logs suggest that the get_valid_write_ids is not cached
for a single query for a single table. It is being called multiple times across
different phases in the compilation of the query. We should verify if we can
safely cache and re use the results. That way we can avoid at the 40-50 ms out
of 678ms compilation time.
{code:java}
2023-09-19T02:55:06,940 INFO [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] ql.Driver: Compiling
command(queryId=rameshkumar_20230919025506_b005cc57-1717-4798-b8da-b502aa7ca3d6):
2023-09-19T02:55:06,967 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2023-09-19T02:55:06,979 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
start=1695117306967 end=1695117306979 duration=12
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
error=false>
2023-09-19T02:55:06,980 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2023-09-19T02:55:06,986 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
start=1695117306980 end=1695117306986 duration=6
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
error=false>
2023-09-19T02:55:06,988 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2023-09-19T02:55:06,995 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
start=1695117306988 end=1695117306995 duration=7
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
error=false>
2023-09-19T02:55:06,997 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2023-09-19T02:55:07,007 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
start=1695117306997 end=1695117307007 duration=10
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
error=false>
2023-09-19T02:55:07,009 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2023-09-19T02:55:07,017 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
start=1695117307009 end=1695117307017 duration=8
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
error=false>
2023-09-19T02:55:07,018 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2023-09-19T02:55:07,026 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
start=1695117307018 end=1695117307026 duration=8
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
error=false>
2023-09-19T02:55:07,059 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2023-09-19T02:55:07,068 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
start=1695117307059 end=1695117307068 duration=9
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
error=false>
2023-09-19T02:55:07,618 INFO [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener at
0.0.0.0/50501] ql.Driver: Completed compiling
command(queryId=rameshkumar_20230919025506_b005cc57-1717-4798-b8da-b502aa7ca3d6);
Time taken: 0.678 seconds{code}
> get_valid_write_ids is being called multiple times for a single query
> ---------------------------------------------------------------------
>
> Key: HIVE-27773
> URL: https://issues.apache.org/jira/browse/HIVE-27773
> Project: Hive
> Issue Type: Task
> Reporter: Ramesh Kumar Thangarajan
> Assignee: Ramesh Kumar Thangarajan
> Priority: Major
>
> Looking at the below logs suggest that the get_valid_write_ids is not cached
> for a single query for a single table. It is being called multiple times
> across different phases in the compilation of the query. We should verify if
> we can safely cache and re use the results. That way we can avoid around
> 40-50 ms out of 678ms compilation time.
>
> {code:java}
> 2023-09-19T02:55:06,940 INFO [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener
> at 0.0.0.0/50501] ql.Driver: Compiling
> command(queryId=rameshkumar_20230919025506_b005cc57-1717-4798-b8da-b502aa7ca3d6):
> 2023-09-19T02:55:06,967 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener
> at 0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
> from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
> 2023-09-19T02:55:06,979 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener
> at 0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
> start=1695117306967 end=1695117306979 duration=12
> from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
> error=false>
> 2023-09-19T02:55:06,980 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener
> at 0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
> from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
> 2023-09-19T02:55:06,986 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener
> at 0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
> start=1695117306980 end=1695117306986 duration=6
> from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
> error=false>
> 2023-09-19T02:55:06,988 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener
> at 0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
> from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
> 2023-09-19T02:55:06,995 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener
> at 0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
> start=1695117306988 end=1695117306995 duration=7
> from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
> error=false>
> 2023-09-19T02:55:06,997 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener
> at 0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
> from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
> 2023-09-19T02:55:07,007 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener
> at 0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
> start=1695117306997 end=1695117307007 duration=10
> from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
> error=false>
> 2023-09-19T02:55:07,009 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener
> at 0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
> from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
> 2023-09-19T02:55:07,017 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener
> at 0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
> start=1695117307009 end=1695117307017 duration=8
> from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
> error=false>
> 2023-09-19T02:55:07,018 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener
> at 0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
> from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
> 2023-09-19T02:55:07,026 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener
> at 0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
> start=1695117307018 end=1695117307026 duration=8
> from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
> error=false>
> 2023-09-19T02:55:07,059 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener
> at 0.0.0.0/50501] metrics.PerfLogger: <PERFLOG method=get_valid_write_ids
> from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
> 2023-09-19T02:55:07,068 DEBUG [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener
> at 0.0.0.0/50501] metrics.PerfLogger: </PERFLOG method=get_valid_write_ids
> start=1695117307059 end=1695117307068 duration=9
> from=org.apache.hadoop.hive.metastore.RetryingHMSHandler retryCount=0
> error=false>
> 2023-09-19T02:55:07,618 INFO [fa0fa087-7e2c-45b8-bd27-b94fbbe23e49 Listener
> at 0.0.0.0/50501] ql.Driver: Completed compiling
> command(queryId=rameshkumar_20230919025506_b005cc57-1717-4798-b8da-b502aa7ca3d6);
> Time taken: 0.678 seconds{code}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
