select on hive table hanging via dcs

[Guy Groulx]

Created hive.hive.tpch10_nation.

From sqlci, select * from hive.hive.tpch10_nation is returned the rows.

But from traci, the same select is simply hanging.

[Suresh Subbiah (suresh-subbiah)]

The problem happens when HiveMetadaData object tries to do an initConnection with a JNI call. The hang occurs on the java side and has this trace found by Hans and Arvind.
Jstack 20514
…
"main" prio=10 tid=0x0000000000f5b000 nid=0x50be in Object.wait() [0x00007fffe57de000]
   java.lang.Thread.State: WAITING (on object monitor)
                at java.lang.Object.wait(Native Method)
                - waiting on <0x00000000f72d9d40> (a java.lang.UNIXProcess)
                at java.lang.Object.wait(Object.java:503)
                at java.lang.UNIXProcess.waitFor(UNIXProcess.java:210)
                - locked <0x00000000f72d9d40> (a java.lang.UNIXProcess)
                at org.apache.hadoop.util.Shell.runCommand(Shell.java:250)
                at org.apache.hadoop.util.Shell.run(Shell.java:188)
                at org.apache.hadoop.util.Shell$ShellCommandExecutor.execute(Shell.java:381)
                at org.apache.hadoop.util.Shell.execCommand(Shell.java:467)
                at org.apache.hadoop.util.Shell.execCommand(Shell.java:450)
                at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getUnixGroups(ShellBasedUnixGroupsMapping.java:86)
                at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getGroups(ShellBasedUnixGroupsMapping.java:55)
                at org.apache.hadoop.security.JniBasedUnixGroupsMappingWithFallback.getGroups(JniBasedUnixGroupsMappingWithFallback.java:50)
                at org.apache.hadoop.security.Groups.getGroups(Groups.java:95)
                at org.apache.hadoop.security.UserGroupInformation.getGroupNames(UserGroupInformation.java:1292)
                - locked <0x00000000fd57d448> (a org.apache.hadoop.security.UserGroupInformation)
                at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.open(HiveMetaStoreClient.java:293)
                at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.<init>(HiveMetaStoreClient.java:163)
                at org.trafodion.sql.HBaseAccess.HiveClient.init(HiveClient.java:85)
…

home/squser2> ps -aef | grep 20514
squser2 20514 18924 0 22:17 ? 00:00:09 mxosrvr -ZkHost n002.cm.cluster:2181,n003.cm.cluster:2181,n004.cm.cluster:2181 -RZ g4q0985.houston.hp.com:175 -ZkPnode /squser2 -CNGTO 60 -ZKSTO 180 -EADSCO 0 -TCPADD 16.235.163.238
squser2 37031 20514 0 22:26 ? 00:00:00 [id] <defunct>

The java layer in mxosrvr fires up a bash shell to to determine the Unix groups for the current user with this command
bash -c id -Gn. Somehow this command never comes back when the process is mxosrvr. It works fine from sqlci. On Spinel we are using a HiveMetastoreServer. It is not clear if this problem could be related. The next step is to check if this problem can be reproduced on a workstation.

[khaled Bouaziz (khaled-bouaziz)]

i changed the importance to critical since we can not load data from hive because of this issue

[khaled Bouaziz (khaled-bouaziz)]

access to hive tables seems to make the session hangs and after doing investication and debugging
it looks like access to the hive meta store tries to run a shell command “bash –c id –Gn trafodion” which seems to die prematurely and the whole session hangs because of that.
After trying different systems we noticed that this issue happens with earlier version of linux (Linux 2.6.32-279.el6.x86_64 -- REDHAT 6.3 for example ) but did not happen with later versions (REDHAT 6.4 for example)

[khaled Bouaziz (khaled-bouaziz)]

This issue maybe due also to using older versions of Linux ( like redhat 6.3 ) and Bright

[Suresh Subbiah (suresh-subbiah)]

This issue can be addressed by setting hive.metastore.execute.setugi to FALSE. This change needs to be in the hive-site.xml file used by Trafodion which can be found in the CLASSPATH. On clusters this is typically at /etc/hive/conf. Please remember to copy the changed hive-site.xml to all nodes.

Making this change may cause permission errors when a hive query is run from the hive shell interface by the trafodion user. Please make sure that trafodion user has sufficient permissions to read and write from the directories used by hive map-reduce jobs.

No change in the Trafodion is planned to address this issue as the problem is elsewhere in the stack and we have a work around to tide us through till the underlying hang problem is resolved in some future version.

[Guy Groulx (guy-groulx)]

I'm changing this to new again as the interface seems to be working again. Currently running with git150105 version

Looking at hive table tpch10_nation, sqlci and trafci.sh both returned the correct number.

However, looking at a bigger table, tpch10_lineitem.

Using HIVE:
/home/squser2> hive
...
Logging initialized using configuration in jar:file:/usr/lib/hive/lib/hive-common-0.12.0-cdh5.1.3.jar!/hive-log4j.properties
hive> select count(*) from tpch10_lineitem;
Total MapReduce jobs = 1
Launching Job 1 out of 1
Number of reduce tasks determined at compile time: 1
In order to change the average load for a reducer (in bytes):
  set hive.exec.reducers.bytes.per.reducer=<number>
In order to limit the maximum number of reducers:
  set hive.exec.reducers.max=<number>
In order to set a constant number of reducers:
  set mapred.reduce.tasks=<number>
Starting Job = job_1415399197193_0005, Tracking URL = http://n009.cm.cluster:8088/proxy/application_1415399197193_0005/
Kill Command = /usr/lib/hadoop/bin/hadoop job -kill job_1415399197193_0005
Hadoop job information for Stage-1: number of mappers: 26; number of reducers: 1
2015-01-09 19:28:41,785 Stage-1 map = 0%, reduce = 0%
2015-01-09 19:28:49,276 Stage-1 map = 4%, reduce = 0%, Cumulative CPU 4.4 sec
2015-01-09 19:28:50,347 Stage-1 map = 8%, reduce = 0%, Cumulative CPU 9.27 sec
2015-01-09 19:28:51,417 Stage-1 map = 15%, reduce = 0%, Cumulative CPU 17.19 sec
2015-01-09 19:28:52,513 Stage-1 map = 65%, reduce = 0%, Cumulative CPU 74.42 sec
2015-01-09 19:28:53,586 Stage-1 map = 81%, reduce = 0%, Cumulative CPU 93.56 sec
2015-01-09 19:28:54,659 Stage-1 map = 81%, reduce = 0%, Cumulative CPU 93.56 sec
2015-01-09 19:28:55,730 Stage-1 map = 96%, reduce = 0%, Cumulative CPU 112.16 sec
2015-01-09 19:28:56,802 Stage-1 map = 100%, reduce = 0%, Cumulative CPU 117.26 sec
2015-01-09 19:28:57,894 Stage-1 map = 100%, reduce = 0%, Cumulative CPU 117.26 sec
2015-01-09 19:28:58,981 Stage-1 map = 100%, reduce = 0%, Cumulative CPU 117.26 sec
2015-01-09 19:29:00,058 Stage-1 map = 100%, reduce = 0%, Cumulative CPU 117.26 sec
2015-01-09 19:29:01,127 Stage-1 map = 100%, reduce = 0%, Cumulative CPU 117.26 sec
2015-01-09 19:29:02,194 Stage-1 map = 100%, reduce = 0%, Cumulative CPU 117.26 sec
2015-01-09 19:29:03,261 Stage-1 map = 100%, reduce = 0%, Cumulative CPU 117.26 sec
2015-01-09 19:29:04,336 Stage-1 map = 100%, reduce = 100%, Cumulative CPU 120.71 sec
2015-01-09 19:29:05,410 Stage-1 map = 100%, reduce = 100%, Cumulative CPU 120.71 sec
MapReduce Total cumulative CPU time: 2 minutes 0 seconds 710 msec
Ended Job = job_1415399197193_0005
MapReduce Jobs Launched:
Job 0: Map: 26 Reduce: 1 Cumulative CPU: 120.71 sec HDFS Read: 7779013570 HDFS Write: 9 SUCCESS
Total MapReduce CPU Time Spent: 2 minutes 0 seconds 710 msec
OK
59986052
Time taken: 46.37 seconds, Fetched: 1 row(s)
hive>

Above is showing total number of rows at 59986052.

From sqlci:
>>select count(*) from tpch10_lineitem;

(EXPR)
--------------------

            59986054

--- 1 row(s) selected.
>>
>>fc
>>select count(*) from tpch10_lineitem;
..

(EXPR)
--------------------

            59986053

--- 1 row(s) se...