Hi,
I have a Presto (322) + Hive (2.3.4) + S3 setup that works fine. A simple
"select count(*) from mydb.mytable" (underneath data is a single 52KB
parquet file on S3) takes 200ms to complete.
I needed fix for https://issues.apache.org/jira/browse/HIVE-21631 so I
dropped in a locally built (from HEAD of master) Hive 4.0. No change to
config under /etc/hive. Now the same query took 20s to complete.
Attached is log from hive-metastore.log during the execution of the query.
Any suggestions on direction of investigation?
-Bowen
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.010689]
2020-03-09T19:35:32,010 INFO [pool-5-thread-1] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=source:10.133.53.23 get_table : tbl=hive.mydb.mytable
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.011562]
2020-03-09T19:35:32,011 INFO [pool-5-thread-1] metastore.HiveMetaStore: 1:
Opening raw store with implementation
class:org.apache.hadoop.hive.metastore.ObjectStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.011743]
2020-03-09T19:35:32,011 INFO [pool-5-thread-1]
metastore.PersistenceManagerProvider: Configuration
datanucleus.autoStartMechanismMode is not set. Defaulting to 'ignored'
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.013398]
2020-03-09T19:35:32,013 INFO [pool-5-thread-1] metastore.ObjectStore:
RawStore: org.apache.hadoop.hive.metastore.ObjectStore@20feeaf1, with
PersistenceManager: null will be shutdown
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.013703]
2020-03-09T19:35:32,013 INFO [pool-5-thread-1] metastore.ObjectStore:
RawStore: org.apache.hadoop.hive.metastore.ObjectStore@20feeaf1, with
PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@5312ffac
created in the thread with id: 54
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.029448]
2020-03-09T19:35:32,029 INFO [pool-5-thread-1] metastore.HiveMetaStore:
Created RawStore: org.apache.hadoop.hive.metastore.ObjectStore@20feeaf1 from
thread id: 54
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.172348]
2020-03-09T19:35:32,172 INFO [pool-5-thread-1] metastore.HiveMetaStore:
Skipping translation for processor with null
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.178310]
2020-03-09T19:35:32,178 INFO [pool-5-thread-1] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Cleaning up thread local RawStore...
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.178356]
2020-03-09T19:35:32,178 INFO [pool-5-thread-1] metastore.ObjectStore:
RawStore: org.apache.hadoop.hive.metastore.ObjectStore@20feeaf1, with
PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@5312ffac will
be shutdown
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.178678]
2020-03-09T19:35:32,178 INFO [pool-5-thread-1] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.192622]
2020-03-09T19:35:32,192 INFO [pool-5-thread-2] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=source:10.133.53.23 get_table : tbl=hive.mydb.mytable
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.193197]
2020-03-09T19:35:32,193 INFO [pool-5-thread-2] metastore.HiveMetaStore: 2:
Opening raw store with implementation
class:org.apache.hadoop.hive.metastore.ObjectStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.193348]
2020-03-09T19:35:32,193 INFO [pool-5-thread-2]
metastore.PersistenceManagerProvider: Configuration
datanucleus.autoStartMechanismMode is not set. Defaulting to 'ignored'
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.194672]
2020-03-09T19:35:32,194 INFO [pool-5-thread-2] metastore.ObjectStore:
RawStore: org.apache.hadoop.hive.metastore.ObjectStore@6e841ca1, with
PersistenceManager: null will be shutdown
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.194948]
2020-03-09T19:35:32,194 INFO [pool-5-thread-2] metastore.ObjectStore:
RawStore: org.apache.hadoop.hive.metastore.ObjectStore@6e841ca1, with
PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@384a5d60
created in the thread with id: 67
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.200707]
2020-03-09T19:35:32,200 INFO [pool-5-thread-2] metastore.HiveMetaStore:
Created RawStore: org.apache.hadoop.hive.metastore.ObjectStore@6e841ca1 from
thread id: 67
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.223618]
2020-03-09T19:35:32,223 INFO [pool-5-thread-2] metastore.HiveMetaStore:
Skipping translation for processor with null
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.224252]
2020-03-09T19:35:32,224 INFO [pool-5-thread-2] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Cleaning up thread local RawStore...
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.224292]
2020-03-09T19:35:32,224 INFO [pool-5-thread-2] metastore.ObjectStore:
RawStore: org.apache.hadoop.hive.metastore.ObjectStore@6e841ca1, with
PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@384a5d60 will
be shutdown
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.224461]
2020-03-09T19:35:32,224 INFO [pool-5-thread-2] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:32.228660]
2020-03-09T19:35:32,228 INFO [pool-5-thread-3] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:33.292074]
2020-03-09T19:35:33,291 INFO [pool-5-thread-4] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:34.312581]
2020-03-09T19:35:34,312 INFO [pool-5-thread-5] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:35.405902]
2020-03-09T19:35:35,405 INFO [pool-5-thread-6] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:36.451363]
2020-03-09T19:35:36,451 INFO [pool-5-thread-7] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:37.550814]
2020-03-09T19:35:37,550 INFO [pool-5-thread-8] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:38.566096]
2020-03-09T19:35:38,565 INFO [pool-5-thread-9] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:39.619569]
2020-03-09T19:35:39,619 INFO [pool-5-thread-10] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:40.681764]
2020-03-09T19:35:40,681 INFO [pool-5-thread-11] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:41.748134]
2020-03-09T19:35:41,747 INFO [pool-5-thread-12] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:41.750212]
2020-03-09T19:35:41,750 INFO [pool-5-thread-13] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=source:10.133.53.23 get_table : tbl=hive.mydb.mytable
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:41.751247]
2020-03-09T19:35:41,751 INFO [pool-5-thread-13] metastore.HiveMetaStore: 13:
Opening raw store with implementation
class:org.apache.hadoop.hive.metastore.ObjectStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:41.751426]
2020-03-09T19:35:41,751 INFO [pool-5-thread-13]
metastore.PersistenceManagerProvider: Configuration
datanucleus.autoStartMechanismMode is not set. Defaulting to 'ignored'
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:41.753243]
2020-03-09T19:35:41,753 INFO [pool-5-thread-13] metastore.ObjectStore:
RawStore: org.apache.hadoop.hive.metastore.ObjectStore@711b9f47, with
PersistenceManager: null will be shutdown
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:41.753654]
2020-03-09T19:35:41,753 INFO [pool-5-thread-13] metastore.ObjectStore:
RawStore: org.apache.hadoop.hive.metastore.ObjectStore@711b9f47, with
PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@44a96a48
created in the thread with id: 78
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:41.770129]
2020-03-09T19:35:41,769 INFO [pool-5-thread-13] metastore.HiveMetaStore:
Created RawStore: org.apache.hadoop.hive.metastore.ObjectStore@711b9f47 from
thread id: 78
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:41.797403]
2020-03-09T19:35:41,797 INFO [pool-5-thread-13] metastore.HiveMetaStore:
Skipping translation for processor with null
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:41.798270]
2020-03-09T19:35:41,798 INFO [pool-5-thread-13] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Cleaning up thread local RawStore...
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:41.798311]
2020-03-09T19:35:41,798 INFO [pool-5-thread-13] metastore.ObjectStore:
RawStore: org.apache.hadoop.hive.metastore.ObjectStore@711b9f47, with
PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@44a96a48 will
be shutdown
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:41.798442]
2020-03-09T19:35:41,798 INFO [pool-5-thread-13] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:41.799294]
2020-03-09T19:35:41,799 INFO [pool-5-thread-14] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:42.803847]
2020-03-09T19:35:42,803 INFO [pool-5-thread-15] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:43.876133]
2020-03-09T19:35:43,876 INFO [pool-5-thread-16] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:44.943427]
2020-03-09T19:35:44,943 INFO [pool-5-thread-17] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:45.947814]
2020-03-09T19:35:45,947 INFO [pool-5-thread-18] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:47.001007]
2020-03-09T19:35:47,000 INFO [pool-5-thread-19] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:48.012187]
2020-03-09T19:35:48,012 INFO [pool-5-thread-20] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:49.097519]
2020-03-09T19:35:49,097 INFO [pool-5-thread-21] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:50.135673]
2020-03-09T19:35:50,135 INFO [pool-5-thread-22] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
@^ r=reporting-data-platform a=unilog-host $@[2020-03-09 19:35:51.194302]
2020-03-09T19:35:51,194 INFO [pool-5-thread-23] HiveMetaStore.audit: ugi=root
ip=10.133.53.23 cmd=Done cleaning up thread local RawStore
