You are viewing a plain text version of this content. The canonical link for it is here.
Posted to mapreduce-user@hadoop.apache.org by Jian Fang <ji...@gmail.com> on 2014/01/08 02:14:48 UTC
A question about Hadoop 1 job user id used for group mapping, which
could lead to performance degradatioin
Hi,
I looked at Hadoop 1.X source code and found some logic that I could not
understand.
In the org.apache.hadoop.mapred.Child class, there were two UGIs defined as
follows.
UserGroupInformation current = UserGroupInformation.getCurrentUser();
current.addToken(jt);
UserGroupInformation taskOwner
=
UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
taskOwner.addToken(jt);
But it is the taskOwner that is actually passed as a UGI to task tracker
and then to HDFS. The first one was not referenced any where.
final TaskUmbilicalProtocol umbilical =
taskOwner.doAs(new PrivilegedExceptionAction<TaskUmbilicalProtocol>()
{
@Override
public TaskUmbilicalProtocol run() throws Exception {
return
(TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
TaskUmbilicalProtocol.versionID,
address,
defaultConf);
}
});
What puzzled me is that the job id is actually passed in as the user name
to task tracker. On the Name node side, when it tries to map the
non-existing user name, i.e., task id, to a group, it always returns empty
array. As a result, we always see annoying warning messages such as
WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler
63 on 9000): No groups available for user job_201401071758_0002
Sometimes, the warning messages were thrown so fast, hundreds or even
thousands per second for a big cluster, the system performance was degraded
dramatically.
Could someone please explain why this logic was designed in this way? Any
benefit to use non-existing user for the group mapping? Or is this a bug?
Thanks in advance,
John
Re: A question about Hadoop 1 job user id used for group mapping, which could lead to performance degradatioin
Posted by Chris Schneider <Sc...@TransPac.com>.
Hi John,
FWIW, setting the log level of org.apache.hadoop.security.UserGroupInformation to ERROR seemed to prevent the fatal NameNode slowdown we ran into. Although I still saw "no such user" Shell$ExitCodeException messages in the logs, these only occurred every few minutes or so. Thus, it seems like this is a reasonable work around until the underlying problem is fixed. I suggest that you file a JIRA ticket, though, as nobody seems to be rushing in here to tell us what we're doing wrong.
Thanks,
- Chris
On Feb 18, 2014, at 5:54 PM, Chris Schneider wrote:
> Hi John,
>
> My AWS Elastic MapReduce NameNode is also filling its log file with messages like the following:
>
> 2014-02-18 23:56:52,344 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 78 on 9000): No groups available for user job_201402182309_0073
> 2014-02-18 23:56:52,351 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 48 on 9000): No groups available for user job_201402182309_0073
> 2014-02-18 23:56:52,356 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 38 on 9000): No groups available for user job_201402182309_0073
>
> I ran into this same issue in March 2013 and got past it by using an m1.xlarge master node (instead of my usual m1.large) when (like right now) I double my slave count (to 32 cc2.8xlarge instances) to re-import a lot of my input data. Using that m1.xlarge didn't prevent the NameNode from logging messages like this, but the beefier instance seemed to weather the load these messages represented better.
>
> Unfortunately, even my m1.xlarge master node now seems overwhelmed. The cluster starts off fine, efficiently mowing through the jobs in my job flow step for a few hours, but it eventually gets into a mode where the copy phase of the reduce jobs appear to make no progress at all. At that point, the NameNode seems to be spending all of its time writing messages like the ones above.
>
> The issue doesn't seem to be related to the NameNode JVM size (I tried increasing it to 4GB before I realized it never used more than ~400MB), nor dfs.namenode.handler.count (which I increased from 64 to 96).
>
> We're currently trying to work around the problem by hacking log4j.properties to set the logging level for org.apache.hadoop.security.UserGroupInformation to ERROR. We might have to do so for the entire package, as I've also seen the following in the NameNode logs:
>
> 2014-02-19 01:01:24,184 WARN org.apache.hadoop.security.ShellBasedUnixGroupsMapping (IPC Server handler 84 on 9000): got exception trying to get groups for user job_201402182309_0226
> org.apache.hadoop.util.Shell$ExitCodeException: id: job_201402182309_0226: No such user
>
> at org.apache.hadoop.util.Shell.runCommand(Shell.java:255)
> at org.apache.hadoop.util.Shell.run(Shell.java:182)
> at org.apache.hadoop.util.Shell$ShellCommandExecutor.execute(Shell.java:375)
> at org.apache.hadoop.util.Shell.execCommand(Shell.java:461)
> at org.apache.hadoop.util.Shell.execCommand(Shell.java:444)
> at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getUnixGroups(ShellBasedUnixGroupsMapping.java:78)
> at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getGroups(ShellBasedUnixGroupsMapping.java:53)
> at org.apache.hadoop.security.Groups.getGroups(Groups.java:79)
> at org.apache.hadoop.security.UserGroupInformation.getGroupNames(UserGroupInformation.java:1037)
> at org.apache.hadoop.hdfs.server.namenode.FSPermissionChecker.<init>(FSPermissionChecker.java:50)
> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkPermission(FSNamesystem.java:5218)
> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkTraverse(FSNamesystem.java:5201)
> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getFileInfo(FSNamesystem.java:2030)
> at org.apache.hadoop.hdfs.server.namenode.NameNode.getFileInfo(NameNode.java:850)
> at sun.reflect.GeneratedMethodAccessor7.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:573)
> at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1393)
> at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1389)
> at java.security.AccessController.doPrivileged(Native Method)
> at javax.security.auth.Subject.doAs(Subject.java:396)
> at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1132)
> at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1387)
>
> I would also be very interested in hearing Jakob Homan and Deveraj Das respond to your analysis of the changes made for MAPREDUCE-1457.
>
> Please post again with any further information you're able to glean about this problem.
>
> Thanks,
>
> - Chris
>
> On Jan 8, 2014, at 1:26 PM, Jian Fang wrote:
>
>> Looked a bit deeper and seems this code was introduced by the following JIRA.
>>
>> https://issues.apache.org/jira/browse/MAPREDUCE-1457
>>
>> There is another related JIRA, i.e., https://issues.apache.org/jira/browse/MAPREDUCE-4329.
>>
>> Perhaps, the warning message is a side effect of JIRA MAPREDUCE-1457 when the cluster is running in non-secured mode. There should be some code path that caused the job id was treated as user name in task tracker or job tracker. Then the job id was passed to HDFS name node. This is definitely a big problem since the heavy warning logs alone degraded the system performance in a relatively big cluster.
>>
>> This behavior is very easy to reproduce by simply running terasort on a cluster.
>>
>> Any suggestion to fix this problem?
>>
>>
>>
>>
>> On Wed, Jan 8, 2014 at 11:18 AM, Jian Fang <ji...@gmail.com> wrote:
>> Thanks Vinod for your quick response. It is running in non-secure mode.
>>
>> I still don't get what is the purpose to use job id in UGI. Could you please explain a bit more?
>>
>> Thanks,
>>
>> John
>>
>>
>> On Wed, Jan 8, 2014 at 10:11 AM, Vinod Kumar Vavilapalli <vi...@hortonworks.com> wrote:
>> It just seems like lazy code. You can see that, later, there is this:
>>
>> {code}
>>
>> for(Token<?> token : UserGroupInformation.getCurrentUser().getTokens()) {
>> childUGI.addToken(token);
>> }
>>
>> {code}
>>
>> So eventually the JobToken is getting added to the UGI which runs task-code.
>>
>> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
>>
>> This seems to be a problem. When the task tries to reach the NameNode, it should do so as the user, not the job-id. It is not just logging, I'd be surprised if jobs pass. Do you have permissions enabled on HDFS?
>>
>> Oh, or is this in non-secure mode (i.e. without kerberos)?
>>
>> +Vinod
>>
>>
>> On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com> wrote:
>>
>> > Hi,
>> >
>> > I looked at Hadoop 1.X source code and found some logic that I could not understand.
>> >
>> > In the org.apache.hadoop.mapred.Child class, there were two UGIs defined as follows.
>> >
>> > UserGroupInformation current = UserGroupInformation.getCurrentUser();
>> > current.addToken(jt);
>> >
>> > UserGroupInformation taskOwner
>> > = UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
>> > taskOwner.addToken(jt);
>> >
>> > But it is the taskOwner that is actually passed as a UGI to task tracker and then to HDFS. The first one was not referenced any where.
>> >
>> > final TaskUmbilicalProtocol umbilical =
>> > taskOwner.doAs(new PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
>> > @Override
>> > public TaskUmbilicalProtocol run() throws Exception {
>> > return (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
>> > TaskUmbilicalProtocol.versionID,
>> > address,
>> > defaultConf);
>> > }
>> > });
>> >
>> > What puzzled me is that the job id is actually passed in as the user name to task tracker. On the Name node side, when it tries to map the non-existing user name, i.e., task id, to a group, it always returns empty array. As a result, we always see annoying warning messages such as
>> >
>> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
>> >
>> > Sometimes, the warning messages were thrown so fast, hundreds or even thousands per second for a big cluster, the system performance was degraded dramatically.
>> >
>> > Could someone please explain why this logic was designed in this way? Any benefit to use non-existing user for the group mapping? Or is this a bug?
>> >
>> > Thanks in advance,
>> >
>> > John
>>
>>
>> --
>> CONFIDENTIALITY NOTICE
>> NOTICE: This message is intended for the use of the individual or entity to
>> which it is addressed and may contain information that is confidential,
>> privileged and exempt from disclosure under applicable law. If the reader
>> of this message is not the intended recipient, you are hereby notified that
>> any printing, copying, dissemination, distribution, disclosure or
>> forwarding of this communication is strictly prohibited. If you have
>> received this communication in error, please contact the sender immediately
>> and delete it from your system. Thank You.
-----------------------------------------
Chris Schneider
http://www.scaleunlimited.com
custom big data solutions
-----------------------------------------
Re: A question about Hadoop 1 job user id used for group mapping, which could lead to performance degradatioin
Posted by Chris Schneider <Sc...@TransPac.com>.
Hi John,
FWIW, setting the log level of org.apache.hadoop.security.UserGroupInformation to ERROR seemed to prevent the fatal NameNode slowdown we ran into. Although I still saw "no such user" Shell$ExitCodeException messages in the logs, these only occurred every few minutes or so. Thus, it seems like this is a reasonable work around until the underlying problem is fixed. I suggest that you file a JIRA ticket, though, as nobody seems to be rushing in here to tell us what we're doing wrong.
Thanks,
- Chris
On Feb 18, 2014, at 5:54 PM, Chris Schneider wrote:
> Hi John,
>
> My AWS Elastic MapReduce NameNode is also filling its log file with messages like the following:
>
> 2014-02-18 23:56:52,344 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 78 on 9000): No groups available for user job_201402182309_0073
> 2014-02-18 23:56:52,351 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 48 on 9000): No groups available for user job_201402182309_0073
> 2014-02-18 23:56:52,356 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 38 on 9000): No groups available for user job_201402182309_0073
>
> I ran into this same issue in March 2013 and got past it by using an m1.xlarge master node (instead of my usual m1.large) when (like right now) I double my slave count (to 32 cc2.8xlarge instances) to re-import a lot of my input data. Using that m1.xlarge didn't prevent the NameNode from logging messages like this, but the beefier instance seemed to weather the load these messages represented better.
>
> Unfortunately, even my m1.xlarge master node now seems overwhelmed. The cluster starts off fine, efficiently mowing through the jobs in my job flow step for a few hours, but it eventually gets into a mode where the copy phase of the reduce jobs appear to make no progress at all. At that point, the NameNode seems to be spending all of its time writing messages like the ones above.
>
> The issue doesn't seem to be related to the NameNode JVM size (I tried increasing it to 4GB before I realized it never used more than ~400MB), nor dfs.namenode.handler.count (which I increased from 64 to 96).
>
> We're currently trying to work around the problem by hacking log4j.properties to set the logging level for org.apache.hadoop.security.UserGroupInformation to ERROR. We might have to do so for the entire package, as I've also seen the following in the NameNode logs:
>
> 2014-02-19 01:01:24,184 WARN org.apache.hadoop.security.ShellBasedUnixGroupsMapping (IPC Server handler 84 on 9000): got exception trying to get groups for user job_201402182309_0226
> org.apache.hadoop.util.Shell$ExitCodeException: id: job_201402182309_0226: No such user
>
> at org.apache.hadoop.util.Shell.runCommand(Shell.java:255)
> at org.apache.hadoop.util.Shell.run(Shell.java:182)
> at org.apache.hadoop.util.Shell$ShellCommandExecutor.execute(Shell.java:375)
> at org.apache.hadoop.util.Shell.execCommand(Shell.java:461)
> at org.apache.hadoop.util.Shell.execCommand(Shell.java:444)
> at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getUnixGroups(ShellBasedUnixGroupsMapping.java:78)
> at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getGroups(ShellBasedUnixGroupsMapping.java:53)
> at org.apache.hadoop.security.Groups.getGroups(Groups.java:79)
> at org.apache.hadoop.security.UserGroupInformation.getGroupNames(UserGroupInformation.java:1037)
> at org.apache.hadoop.hdfs.server.namenode.FSPermissionChecker.<init>(FSPermissionChecker.java:50)
> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkPermission(FSNamesystem.java:5218)
> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkTraverse(FSNamesystem.java:5201)
> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getFileInfo(FSNamesystem.java:2030)
> at org.apache.hadoop.hdfs.server.namenode.NameNode.getFileInfo(NameNode.java:850)
> at sun.reflect.GeneratedMethodAccessor7.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:573)
> at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1393)
> at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1389)
> at java.security.AccessController.doPrivileged(Native Method)
> at javax.security.auth.Subject.doAs(Subject.java:396)
> at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1132)
> at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1387)
>
> I would also be very interested in hearing Jakob Homan and Deveraj Das respond to your analysis of the changes made for MAPREDUCE-1457.
>
> Please post again with any further information you're able to glean about this problem.
>
> Thanks,
>
> - Chris
>
> On Jan 8, 2014, at 1:26 PM, Jian Fang wrote:
>
>> Looked a bit deeper and seems this code was introduced by the following JIRA.
>>
>> https://issues.apache.org/jira/browse/MAPREDUCE-1457
>>
>> There is another related JIRA, i.e., https://issues.apache.org/jira/browse/MAPREDUCE-4329.
>>
>> Perhaps, the warning message is a side effect of JIRA MAPREDUCE-1457 when the cluster is running in non-secured mode. There should be some code path that caused the job id was treated as user name in task tracker or job tracker. Then the job id was passed to HDFS name node. This is definitely a big problem since the heavy warning logs alone degraded the system performance in a relatively big cluster.
>>
>> This behavior is very easy to reproduce by simply running terasort on a cluster.
>>
>> Any suggestion to fix this problem?
>>
>>
>>
>>
>> On Wed, Jan 8, 2014 at 11:18 AM, Jian Fang <ji...@gmail.com> wrote:
>> Thanks Vinod for your quick response. It is running in non-secure mode.
>>
>> I still don't get what is the purpose to use job id in UGI. Could you please explain a bit more?
>>
>> Thanks,
>>
>> John
>>
>>
>> On Wed, Jan 8, 2014 at 10:11 AM, Vinod Kumar Vavilapalli <vi...@hortonworks.com> wrote:
>> It just seems like lazy code. You can see that, later, there is this:
>>
>> {code}
>>
>> for(Token<?> token : UserGroupInformation.getCurrentUser().getTokens()) {
>> childUGI.addToken(token);
>> }
>>
>> {code}
>>
>> So eventually the JobToken is getting added to the UGI which runs task-code.
>>
>> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
>>
>> This seems to be a problem. When the task tries to reach the NameNode, it should do so as the user, not the job-id. It is not just logging, I'd be surprised if jobs pass. Do you have permissions enabled on HDFS?
>>
>> Oh, or is this in non-secure mode (i.e. without kerberos)?
>>
>> +Vinod
>>
>>
>> On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com> wrote:
>>
>> > Hi,
>> >
>> > I looked at Hadoop 1.X source code and found some logic that I could not understand.
>> >
>> > In the org.apache.hadoop.mapred.Child class, there were two UGIs defined as follows.
>> >
>> > UserGroupInformation current = UserGroupInformation.getCurrentUser();
>> > current.addToken(jt);
>> >
>> > UserGroupInformation taskOwner
>> > = UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
>> > taskOwner.addToken(jt);
>> >
>> > But it is the taskOwner that is actually passed as a UGI to task tracker and then to HDFS. The first one was not referenced any where.
>> >
>> > final TaskUmbilicalProtocol umbilical =
>> > taskOwner.doAs(new PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
>> > @Override
>> > public TaskUmbilicalProtocol run() throws Exception {
>> > return (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
>> > TaskUmbilicalProtocol.versionID,
>> > address,
>> > defaultConf);
>> > }
>> > });
>> >
>> > What puzzled me is that the job id is actually passed in as the user name to task tracker. On the Name node side, when it tries to map the non-existing user name, i.e., task id, to a group, it always returns empty array. As a result, we always see annoying warning messages such as
>> >
>> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
>> >
>> > Sometimes, the warning messages were thrown so fast, hundreds or even thousands per second for a big cluster, the system performance was degraded dramatically.
>> >
>> > Could someone please explain why this logic was designed in this way? Any benefit to use non-existing user for the group mapping? Or is this a bug?
>> >
>> > Thanks in advance,
>> >
>> > John
>>
>>
>> --
>> CONFIDENTIALITY NOTICE
>> NOTICE: This message is intended for the use of the individual or entity to
>> which it is addressed and may contain information that is confidential,
>> privileged and exempt from disclosure under applicable law. If the reader
>> of this message is not the intended recipient, you are hereby notified that
>> any printing, copying, dissemination, distribution, disclosure or
>> forwarding of this communication is strictly prohibited. If you have
>> received this communication in error, please contact the sender immediately
>> and delete it from your system. Thank You.
-----------------------------------------
Chris Schneider
http://www.scaleunlimited.com
custom big data solutions
-----------------------------------------
Re: A question about Hadoop 1 job user id used for group mapping, which could lead to performance degradatioin
Posted by Chris Schneider <Sc...@TransPac.com>.
Hi John,
FWIW, setting the log level of org.apache.hadoop.security.UserGroupInformation to ERROR seemed to prevent the fatal NameNode slowdown we ran into. Although I still saw "no such user" Shell$ExitCodeException messages in the logs, these only occurred every few minutes or so. Thus, it seems like this is a reasonable work around until the underlying problem is fixed. I suggest that you file a JIRA ticket, though, as nobody seems to be rushing in here to tell us what we're doing wrong.
Thanks,
- Chris
On Feb 18, 2014, at 5:54 PM, Chris Schneider wrote:
> Hi John,
>
> My AWS Elastic MapReduce NameNode is also filling its log file with messages like the following:
>
> 2014-02-18 23:56:52,344 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 78 on 9000): No groups available for user job_201402182309_0073
> 2014-02-18 23:56:52,351 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 48 on 9000): No groups available for user job_201402182309_0073
> 2014-02-18 23:56:52,356 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 38 on 9000): No groups available for user job_201402182309_0073
>
> I ran into this same issue in March 2013 and got past it by using an m1.xlarge master node (instead of my usual m1.large) when (like right now) I double my slave count (to 32 cc2.8xlarge instances) to re-import a lot of my input data. Using that m1.xlarge didn't prevent the NameNode from logging messages like this, but the beefier instance seemed to weather the load these messages represented better.
>
> Unfortunately, even my m1.xlarge master node now seems overwhelmed. The cluster starts off fine, efficiently mowing through the jobs in my job flow step for a few hours, but it eventually gets into a mode where the copy phase of the reduce jobs appear to make no progress at all. At that point, the NameNode seems to be spending all of its time writing messages like the ones above.
>
> The issue doesn't seem to be related to the NameNode JVM size (I tried increasing it to 4GB before I realized it never used more than ~400MB), nor dfs.namenode.handler.count (which I increased from 64 to 96).
>
> We're currently trying to work around the problem by hacking log4j.properties to set the logging level for org.apache.hadoop.security.UserGroupInformation to ERROR. We might have to do so for the entire package, as I've also seen the following in the NameNode logs:
>
> 2014-02-19 01:01:24,184 WARN org.apache.hadoop.security.ShellBasedUnixGroupsMapping (IPC Server handler 84 on 9000): got exception trying to get groups for user job_201402182309_0226
> org.apache.hadoop.util.Shell$ExitCodeException: id: job_201402182309_0226: No such user
>
> at org.apache.hadoop.util.Shell.runCommand(Shell.java:255)
> at org.apache.hadoop.util.Shell.run(Shell.java:182)
> at org.apache.hadoop.util.Shell$ShellCommandExecutor.execute(Shell.java:375)
> at org.apache.hadoop.util.Shell.execCommand(Shell.java:461)
> at org.apache.hadoop.util.Shell.execCommand(Shell.java:444)
> at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getUnixGroups(ShellBasedUnixGroupsMapping.java:78)
> at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getGroups(ShellBasedUnixGroupsMapping.java:53)
> at org.apache.hadoop.security.Groups.getGroups(Groups.java:79)
> at org.apache.hadoop.security.UserGroupInformation.getGroupNames(UserGroupInformation.java:1037)
> at org.apache.hadoop.hdfs.server.namenode.FSPermissionChecker.<init>(FSPermissionChecker.java:50)
> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkPermission(FSNamesystem.java:5218)
> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkTraverse(FSNamesystem.java:5201)
> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getFileInfo(FSNamesystem.java:2030)
> at org.apache.hadoop.hdfs.server.namenode.NameNode.getFileInfo(NameNode.java:850)
> at sun.reflect.GeneratedMethodAccessor7.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:573)
> at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1393)
> at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1389)
> at java.security.AccessController.doPrivileged(Native Method)
> at javax.security.auth.Subject.doAs(Subject.java:396)
> at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1132)
> at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1387)
>
> I would also be very interested in hearing Jakob Homan and Deveraj Das respond to your analysis of the changes made for MAPREDUCE-1457.
>
> Please post again with any further information you're able to glean about this problem.
>
> Thanks,
>
> - Chris
>
> On Jan 8, 2014, at 1:26 PM, Jian Fang wrote:
>
>> Looked a bit deeper and seems this code was introduced by the following JIRA.
>>
>> https://issues.apache.org/jira/browse/MAPREDUCE-1457
>>
>> There is another related JIRA, i.e., https://issues.apache.org/jira/browse/MAPREDUCE-4329.
>>
>> Perhaps, the warning message is a side effect of JIRA MAPREDUCE-1457 when the cluster is running in non-secured mode. There should be some code path that caused the job id was treated as user name in task tracker or job tracker. Then the job id was passed to HDFS name node. This is definitely a big problem since the heavy warning logs alone degraded the system performance in a relatively big cluster.
>>
>> This behavior is very easy to reproduce by simply running terasort on a cluster.
>>
>> Any suggestion to fix this problem?
>>
>>
>>
>>
>> On Wed, Jan 8, 2014 at 11:18 AM, Jian Fang <ji...@gmail.com> wrote:
>> Thanks Vinod for your quick response. It is running in non-secure mode.
>>
>> I still don't get what is the purpose to use job id in UGI. Could you please explain a bit more?
>>
>> Thanks,
>>
>> John
>>
>>
>> On Wed, Jan 8, 2014 at 10:11 AM, Vinod Kumar Vavilapalli <vi...@hortonworks.com> wrote:
>> It just seems like lazy code. You can see that, later, there is this:
>>
>> {code}
>>
>> for(Token<?> token : UserGroupInformation.getCurrentUser().getTokens()) {
>> childUGI.addToken(token);
>> }
>>
>> {code}
>>
>> So eventually the JobToken is getting added to the UGI which runs task-code.
>>
>> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
>>
>> This seems to be a problem. When the task tries to reach the NameNode, it should do so as the user, not the job-id. It is not just logging, I'd be surprised if jobs pass. Do you have permissions enabled on HDFS?
>>
>> Oh, or is this in non-secure mode (i.e. without kerberos)?
>>
>> +Vinod
>>
>>
>> On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com> wrote:
>>
>> > Hi,
>> >
>> > I looked at Hadoop 1.X source code and found some logic that I could not understand.
>> >
>> > In the org.apache.hadoop.mapred.Child class, there were two UGIs defined as follows.
>> >
>> > UserGroupInformation current = UserGroupInformation.getCurrentUser();
>> > current.addToken(jt);
>> >
>> > UserGroupInformation taskOwner
>> > = UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
>> > taskOwner.addToken(jt);
>> >
>> > But it is the taskOwner that is actually passed as a UGI to task tracker and then to HDFS. The first one was not referenced any where.
>> >
>> > final TaskUmbilicalProtocol umbilical =
>> > taskOwner.doAs(new PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
>> > @Override
>> > public TaskUmbilicalProtocol run() throws Exception {
>> > return (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
>> > TaskUmbilicalProtocol.versionID,
>> > address,
>> > defaultConf);
>> > }
>> > });
>> >
>> > What puzzled me is that the job id is actually passed in as the user name to task tracker. On the Name node side, when it tries to map the non-existing user name, i.e., task id, to a group, it always returns empty array. As a result, we always see annoying warning messages such as
>> >
>> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
>> >
>> > Sometimes, the warning messages were thrown so fast, hundreds or even thousands per second for a big cluster, the system performance was degraded dramatically.
>> >
>> > Could someone please explain why this logic was designed in this way? Any benefit to use non-existing user for the group mapping? Or is this a bug?
>> >
>> > Thanks in advance,
>> >
>> > John
>>
>>
>> --
>> CONFIDENTIALITY NOTICE
>> NOTICE: This message is intended for the use of the individual or entity to
>> which it is addressed and may contain information that is confidential,
>> privileged and exempt from disclosure under applicable law. If the reader
>> of this message is not the intended recipient, you are hereby notified that
>> any printing, copying, dissemination, distribution, disclosure or
>> forwarding of this communication is strictly prohibited. If you have
>> received this communication in error, please contact the sender immediately
>> and delete it from your system. Thank You.
-----------------------------------------
Chris Schneider
http://www.scaleunlimited.com
custom big data solutions
-----------------------------------------
Re: A question about Hadoop 1 job user id used for group mapping, which could lead to performance degradatioin
Posted by Chris Schneider <Sc...@TransPac.com>.
Hi John,
FWIW, setting the log level of org.apache.hadoop.security.UserGroupInformation to ERROR seemed to prevent the fatal NameNode slowdown we ran into. Although I still saw "no such user" Shell$ExitCodeException messages in the logs, these only occurred every few minutes or so. Thus, it seems like this is a reasonable work around until the underlying problem is fixed. I suggest that you file a JIRA ticket, though, as nobody seems to be rushing in here to tell us what we're doing wrong.
Thanks,
- Chris
On Feb 18, 2014, at 5:54 PM, Chris Schneider wrote:
> Hi John,
>
> My AWS Elastic MapReduce NameNode is also filling its log file with messages like the following:
>
> 2014-02-18 23:56:52,344 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 78 on 9000): No groups available for user job_201402182309_0073
> 2014-02-18 23:56:52,351 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 48 on 9000): No groups available for user job_201402182309_0073
> 2014-02-18 23:56:52,356 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 38 on 9000): No groups available for user job_201402182309_0073
>
> I ran into this same issue in March 2013 and got past it by using an m1.xlarge master node (instead of my usual m1.large) when (like right now) I double my slave count (to 32 cc2.8xlarge instances) to re-import a lot of my input data. Using that m1.xlarge didn't prevent the NameNode from logging messages like this, but the beefier instance seemed to weather the load these messages represented better.
>
> Unfortunately, even my m1.xlarge master node now seems overwhelmed. The cluster starts off fine, efficiently mowing through the jobs in my job flow step for a few hours, but it eventually gets into a mode where the copy phase of the reduce jobs appear to make no progress at all. At that point, the NameNode seems to be spending all of its time writing messages like the ones above.
>
> The issue doesn't seem to be related to the NameNode JVM size (I tried increasing it to 4GB before I realized it never used more than ~400MB), nor dfs.namenode.handler.count (which I increased from 64 to 96).
>
> We're currently trying to work around the problem by hacking log4j.properties to set the logging level for org.apache.hadoop.security.UserGroupInformation to ERROR. We might have to do so for the entire package, as I've also seen the following in the NameNode logs:
>
> 2014-02-19 01:01:24,184 WARN org.apache.hadoop.security.ShellBasedUnixGroupsMapping (IPC Server handler 84 on 9000): got exception trying to get groups for user job_201402182309_0226
> org.apache.hadoop.util.Shell$ExitCodeException: id: job_201402182309_0226: No such user
>
> at org.apache.hadoop.util.Shell.runCommand(Shell.java:255)
> at org.apache.hadoop.util.Shell.run(Shell.java:182)
> at org.apache.hadoop.util.Shell$ShellCommandExecutor.execute(Shell.java:375)
> at org.apache.hadoop.util.Shell.execCommand(Shell.java:461)
> at org.apache.hadoop.util.Shell.execCommand(Shell.java:444)
> at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getUnixGroups(ShellBasedUnixGroupsMapping.java:78)
> at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getGroups(ShellBasedUnixGroupsMapping.java:53)
> at org.apache.hadoop.security.Groups.getGroups(Groups.java:79)
> at org.apache.hadoop.security.UserGroupInformation.getGroupNames(UserGroupInformation.java:1037)
> at org.apache.hadoop.hdfs.server.namenode.FSPermissionChecker.<init>(FSPermissionChecker.java:50)
> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkPermission(FSNamesystem.java:5218)
> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkTraverse(FSNamesystem.java:5201)
> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getFileInfo(FSNamesystem.java:2030)
> at org.apache.hadoop.hdfs.server.namenode.NameNode.getFileInfo(NameNode.java:850)
> at sun.reflect.GeneratedMethodAccessor7.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:573)
> at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1393)
> at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1389)
> at java.security.AccessController.doPrivileged(Native Method)
> at javax.security.auth.Subject.doAs(Subject.java:396)
> at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1132)
> at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1387)
>
> I would also be very interested in hearing Jakob Homan and Deveraj Das respond to your analysis of the changes made for MAPREDUCE-1457.
>
> Please post again with any further information you're able to glean about this problem.
>
> Thanks,
>
> - Chris
>
> On Jan 8, 2014, at 1:26 PM, Jian Fang wrote:
>
>> Looked a bit deeper and seems this code was introduced by the following JIRA.
>>
>> https://issues.apache.org/jira/browse/MAPREDUCE-1457
>>
>> There is another related JIRA, i.e., https://issues.apache.org/jira/browse/MAPREDUCE-4329.
>>
>> Perhaps, the warning message is a side effect of JIRA MAPREDUCE-1457 when the cluster is running in non-secured mode. There should be some code path that caused the job id was treated as user name in task tracker or job tracker. Then the job id was passed to HDFS name node. This is definitely a big problem since the heavy warning logs alone degraded the system performance in a relatively big cluster.
>>
>> This behavior is very easy to reproduce by simply running terasort on a cluster.
>>
>> Any suggestion to fix this problem?
>>
>>
>>
>>
>> On Wed, Jan 8, 2014 at 11:18 AM, Jian Fang <ji...@gmail.com> wrote:
>> Thanks Vinod for your quick response. It is running in non-secure mode.
>>
>> I still don't get what is the purpose to use job id in UGI. Could you please explain a bit more?
>>
>> Thanks,
>>
>> John
>>
>>
>> On Wed, Jan 8, 2014 at 10:11 AM, Vinod Kumar Vavilapalli <vi...@hortonworks.com> wrote:
>> It just seems like lazy code. You can see that, later, there is this:
>>
>> {code}
>>
>> for(Token<?> token : UserGroupInformation.getCurrentUser().getTokens()) {
>> childUGI.addToken(token);
>> }
>>
>> {code}
>>
>> So eventually the JobToken is getting added to the UGI which runs task-code.
>>
>> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
>>
>> This seems to be a problem. When the task tries to reach the NameNode, it should do so as the user, not the job-id. It is not just logging, I'd be surprised if jobs pass. Do you have permissions enabled on HDFS?
>>
>> Oh, or is this in non-secure mode (i.e. without kerberos)?
>>
>> +Vinod
>>
>>
>> On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com> wrote:
>>
>> > Hi,
>> >
>> > I looked at Hadoop 1.X source code and found some logic that I could not understand.
>> >
>> > In the org.apache.hadoop.mapred.Child class, there were two UGIs defined as follows.
>> >
>> > UserGroupInformation current = UserGroupInformation.getCurrentUser();
>> > current.addToken(jt);
>> >
>> > UserGroupInformation taskOwner
>> > = UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
>> > taskOwner.addToken(jt);
>> >
>> > But it is the taskOwner that is actually passed as a UGI to task tracker and then to HDFS. The first one was not referenced any where.
>> >
>> > final TaskUmbilicalProtocol umbilical =
>> > taskOwner.doAs(new PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
>> > @Override
>> > public TaskUmbilicalProtocol run() throws Exception {
>> > return (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
>> > TaskUmbilicalProtocol.versionID,
>> > address,
>> > defaultConf);
>> > }
>> > });
>> >
>> > What puzzled me is that the job id is actually passed in as the user name to task tracker. On the Name node side, when it tries to map the non-existing user name, i.e., task id, to a group, it always returns empty array. As a result, we always see annoying warning messages such as
>> >
>> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
>> >
>> > Sometimes, the warning messages were thrown so fast, hundreds or even thousands per second for a big cluster, the system performance was degraded dramatically.
>> >
>> > Could someone please explain why this logic was designed in this way? Any benefit to use non-existing user for the group mapping? Or is this a bug?
>> >
>> > Thanks in advance,
>> >
>> > John
>>
>>
>> --
>> CONFIDENTIALITY NOTICE
>> NOTICE: This message is intended for the use of the individual or entity to
>> which it is addressed and may contain information that is confidential,
>> privileged and exempt from disclosure under applicable law. If the reader
>> of this message is not the intended recipient, you are hereby notified that
>> any printing, copying, dissemination, distribution, disclosure or
>> forwarding of this communication is strictly prohibited. If you have
>> received this communication in error, please contact the sender immediately
>> and delete it from your system. Thank You.
-----------------------------------------
Chris Schneider
http://www.scaleunlimited.com
custom big data solutions
-----------------------------------------
Re: A question about Hadoop 1 job user id used for group mapping, which could lead to performance degradatioin
Posted by Chris Schneider <Sc...@TransPac.com>.
Hi John,
My AWS Elastic MapReduce NameNode is also filling its log file with messages like the following:
2014-02-18 23:56:52,344 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 78 on 9000): No groups available for user job_201402182309_0073
2014-02-18 23:56:52,351 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 48 on 9000): No groups available for user job_201402182309_0073
2014-02-18 23:56:52,356 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 38 on 9000): No groups available for user job_201402182309_0073
I ran into this same issue in March 2013 and got past it by using an m1.xlarge master node (instead of my usual m1.large) when (like right now) I double my slave count (to 32 cc2.8xlarge instances) to re-import a lot of my input data. Using that m1.xlarge didn't prevent the NameNode from logging messages like this, but the beefier instance seemed to weather the load these messages represented better.
Unfortunately, even my m1.xlarge master node now seems overwhelmed. The cluster starts off fine, efficiently mowing through the jobs in my job flow step for a few hours, but it eventually gets into a mode where the copy phase of the reduce jobs appear to make no progress at all. At that point, the NameNode seems to be spending all of its time writing messages like the ones above.
The issue doesn't seem to be related to the NameNode JVM size (I tried increasing it to 4GB before I realized it never used more than ~400MB), nor dfs.namenode.handler.count (which I increased from 64 to 96).
We're currently trying to work around the problem by hacking log4j.properties to set the logging level for org.apache.hadoop.security.UserGroupInformation to ERROR. We might have to do so for the entire package, as I've also seen the following in the NameNode logs:
2014-02-19 01:01:24,184 WARN org.apache.hadoop.security.ShellBasedUnixGroupsMapping (IPC Server handler 84 on 9000): got exception trying to get groups for user job_201402182309_0226
org.apache.hadoop.util.Shell$ExitCodeException: id: job_201402182309_0226: No such user
at org.apache.hadoop.util.Shell.runCommand(Shell.java:255)
at org.apache.hadoop.util.Shell.run(Shell.java:182)
at org.apache.hadoop.util.Shell$ShellCommandExecutor.execute(Shell.java:375)
at org.apache.hadoop.util.Shell.execCommand(Shell.java:461)
at org.apache.hadoop.util.Shell.execCommand(Shell.java:444)
at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getUnixGroups(ShellBasedUnixGroupsMapping.java:78)
at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getGroups(ShellBasedUnixGroupsMapping.java:53)
at org.apache.hadoop.security.Groups.getGroups(Groups.java:79)
at org.apache.hadoop.security.UserGroupInformation.getGroupNames(UserGroupInformation.java:1037)
at org.apache.hadoop.hdfs.server.namenode.FSPermissionChecker.<init>(FSPermissionChecker.java:50)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkPermission(FSNamesystem.java:5218)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkTraverse(FSNamesystem.java:5201)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getFileInfo(FSNamesystem.java:2030)
at org.apache.hadoop.hdfs.server.namenode.NameNode.getFileInfo(NameNode.java:850)
at sun.reflect.GeneratedMethodAccessor7.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:573)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1393)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1389)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:396)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1132)
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1387)
I would also be very interested in hearing Jakob Homan and Deveraj Das respond to your analysis of the changes made for MAPREDUCE-1457.
Please post again with any further information you're able to glean about this problem.
Thanks,
- Chris
On Jan 8, 2014, at 1:26 PM, Jian Fang wrote:
> Looked a bit deeper and seems this code was introduced by the following JIRA.
>
> https://issues.apache.org/jira/browse/MAPREDUCE-1457
>
> There is another related JIRA, i.e., https://issues.apache.org/jira/browse/MAPREDUCE-4329.
>
> Perhaps, the warning message is a side effect of JIRA MAPREDUCE-1457 when the cluster is running in non-secured mode. There should be some code path that caused the job id was treated as user name in task tracker or job tracker. Then the job id was passed to HDFS name node. This is definitely a big problem since the heavy warning logs alone degraded the system performance in a relatively big cluster.
>
> This behavior is very easy to reproduce by simply running terasort on a cluster.
>
> Any suggestion to fix this problem?
>
>
>
>
> On Wed, Jan 8, 2014 at 11:18 AM, Jian Fang <ji...@gmail.com> wrote:
> Thanks Vinod for your quick response. It is running in non-secure mode.
>
> I still don't get what is the purpose to use job id in UGI. Could you please explain a bit more?
>
> Thanks,
>
> John
>
>
> On Wed, Jan 8, 2014 at 10:11 AM, Vinod Kumar Vavilapalli <vi...@hortonworks.com> wrote:
> It just seems like lazy code. You can see that, later, there is this:
>
> {code}
>
> for(Token<?> token : UserGroupInformation.getCurrentUser().getTokens()) {
> childUGI.addToken(token);
> }
>
> {code}
>
> So eventually the JobToken is getting added to the UGI which runs task-code.
>
> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
>
> This seems to be a problem. When the task tries to reach the NameNode, it should do so as the user, not the job-id. It is not just logging, I'd be surprised if jobs pass. Do you have permissions enabled on HDFS?
>
> Oh, or is this in non-secure mode (i.e. without kerberos)?
>
> +Vinod
>
>
> On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com> wrote:
>
> > Hi,
> >
> > I looked at Hadoop 1.X source code and found some logic that I could not understand.
> >
> > In the org.apache.hadoop.mapred.Child class, there were two UGIs defined as follows.
> >
> > UserGroupInformation current = UserGroupInformation.getCurrentUser();
> > current.addToken(jt);
> >
> > UserGroupInformation taskOwner
> > = UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
> > taskOwner.addToken(jt);
> >
> > But it is the taskOwner that is actually passed as a UGI to task tracker and then to HDFS. The first one was not referenced any where.
> >
> > final TaskUmbilicalProtocol umbilical =
> > taskOwner.doAs(new PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
> > @Override
> > public TaskUmbilicalProtocol run() throws Exception {
> > return (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
> > TaskUmbilicalProtocol.versionID,
> > address,
> > defaultConf);
> > }
> > });
> >
> > What puzzled me is that the job id is actually passed in as the user name to task tracker. On the Name node side, when it tries to map the non-existing user name, i.e., task id, to a group, it always returns empty array. As a result, we always see annoying warning messages such as
> >
> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
> >
> > Sometimes, the warning messages were thrown so fast, hundreds or even thousands per second for a big cluster, the system performance was degraded dramatically.
> >
> > Could someone please explain why this logic was designed in this way? Any benefit to use non-existing user for the group mapping? Or is this a bug?
> >
> > Thanks in advance,
> >
> > John
>
>
> --
> CONFIDENTIALITY NOTICE
> NOTICE: This message is intended for the use of the individual or entity to
> which it is addressed and may contain information that is confidential,
> privileged and exempt from disclosure under applicable law. If the reader
> of this message is not the intended recipient, you are hereby notified that
> any printing, copying, dissemination, distribution, disclosure or
> forwarding of this communication is strictly prohibited. If you have
> received this communication in error, please contact the sender immediately
> and delete it from your system. Thank You.
-----------------------------------------
Chris Schneider
http://www.scaleunlimited.com
custom big data solutions
-----------------------------------------
Re: A question about Hadoop 1 job user id used for group mapping, which could lead to performance degradatioin
Posted by Chris Schneider <Sc...@TransPac.com>.
Hi John,
My AWS Elastic MapReduce NameNode is also filling its log file with messages like the following:
2014-02-18 23:56:52,344 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 78 on 9000): No groups available for user job_201402182309_0073
2014-02-18 23:56:52,351 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 48 on 9000): No groups available for user job_201402182309_0073
2014-02-18 23:56:52,356 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 38 on 9000): No groups available for user job_201402182309_0073
I ran into this same issue in March 2013 and got past it by using an m1.xlarge master node (instead of my usual m1.large) when (like right now) I double my slave count (to 32 cc2.8xlarge instances) to re-import a lot of my input data. Using that m1.xlarge didn't prevent the NameNode from logging messages like this, but the beefier instance seemed to weather the load these messages represented better.
Unfortunately, even my m1.xlarge master node now seems overwhelmed. The cluster starts off fine, efficiently mowing through the jobs in my job flow step for a few hours, but it eventually gets into a mode where the copy phase of the reduce jobs appear to make no progress at all. At that point, the NameNode seems to be spending all of its time writing messages like the ones above.
The issue doesn't seem to be related to the NameNode JVM size (I tried increasing it to 4GB before I realized it never used more than ~400MB), nor dfs.namenode.handler.count (which I increased from 64 to 96).
We're currently trying to work around the problem by hacking log4j.properties to set the logging level for org.apache.hadoop.security.UserGroupInformation to ERROR. We might have to do so for the entire package, as I've also seen the following in the NameNode logs:
2014-02-19 01:01:24,184 WARN org.apache.hadoop.security.ShellBasedUnixGroupsMapping (IPC Server handler 84 on 9000): got exception trying to get groups for user job_201402182309_0226
org.apache.hadoop.util.Shell$ExitCodeException: id: job_201402182309_0226: No such user
at org.apache.hadoop.util.Shell.runCommand(Shell.java:255)
at org.apache.hadoop.util.Shell.run(Shell.java:182)
at org.apache.hadoop.util.Shell$ShellCommandExecutor.execute(Shell.java:375)
at org.apache.hadoop.util.Shell.execCommand(Shell.java:461)
at org.apache.hadoop.util.Shell.execCommand(Shell.java:444)
at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getUnixGroups(ShellBasedUnixGroupsMapping.java:78)
at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getGroups(ShellBasedUnixGroupsMapping.java:53)
at org.apache.hadoop.security.Groups.getGroups(Groups.java:79)
at org.apache.hadoop.security.UserGroupInformation.getGroupNames(UserGroupInformation.java:1037)
at org.apache.hadoop.hdfs.server.namenode.FSPermissionChecker.<init>(FSPermissionChecker.java:50)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkPermission(FSNamesystem.java:5218)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkTraverse(FSNamesystem.java:5201)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getFileInfo(FSNamesystem.java:2030)
at org.apache.hadoop.hdfs.server.namenode.NameNode.getFileInfo(NameNode.java:850)
at sun.reflect.GeneratedMethodAccessor7.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:573)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1393)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1389)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:396)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1132)
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1387)
I would also be very interested in hearing Jakob Homan and Deveraj Das respond to your analysis of the changes made for MAPREDUCE-1457.
Please post again with any further information you're able to glean about this problem.
Thanks,
- Chris
On Jan 8, 2014, at 1:26 PM, Jian Fang wrote:
> Looked a bit deeper and seems this code was introduced by the following JIRA.
>
> https://issues.apache.org/jira/browse/MAPREDUCE-1457
>
> There is another related JIRA, i.e., https://issues.apache.org/jira/browse/MAPREDUCE-4329.
>
> Perhaps, the warning message is a side effect of JIRA MAPREDUCE-1457 when the cluster is running in non-secured mode. There should be some code path that caused the job id was treated as user name in task tracker or job tracker. Then the job id was passed to HDFS name node. This is definitely a big problem since the heavy warning logs alone degraded the system performance in a relatively big cluster.
>
> This behavior is very easy to reproduce by simply running terasort on a cluster.
>
> Any suggestion to fix this problem?
>
>
>
>
> On Wed, Jan 8, 2014 at 11:18 AM, Jian Fang <ji...@gmail.com> wrote:
> Thanks Vinod for your quick response. It is running in non-secure mode.
>
> I still don't get what is the purpose to use job id in UGI. Could you please explain a bit more?
>
> Thanks,
>
> John
>
>
> On Wed, Jan 8, 2014 at 10:11 AM, Vinod Kumar Vavilapalli <vi...@hortonworks.com> wrote:
> It just seems like lazy code. You can see that, later, there is this:
>
> {code}
>
> for(Token<?> token : UserGroupInformation.getCurrentUser().getTokens()) {
> childUGI.addToken(token);
> }
>
> {code}
>
> So eventually the JobToken is getting added to the UGI which runs task-code.
>
> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
>
> This seems to be a problem. When the task tries to reach the NameNode, it should do so as the user, not the job-id. It is not just logging, I'd be surprised if jobs pass. Do you have permissions enabled on HDFS?
>
> Oh, or is this in non-secure mode (i.e. without kerberos)?
>
> +Vinod
>
>
> On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com> wrote:
>
> > Hi,
> >
> > I looked at Hadoop 1.X source code and found some logic that I could not understand.
> >
> > In the org.apache.hadoop.mapred.Child class, there were two UGIs defined as follows.
> >
> > UserGroupInformation current = UserGroupInformation.getCurrentUser();
> > current.addToken(jt);
> >
> > UserGroupInformation taskOwner
> > = UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
> > taskOwner.addToken(jt);
> >
> > But it is the taskOwner that is actually passed as a UGI to task tracker and then to HDFS. The first one was not referenced any where.
> >
> > final TaskUmbilicalProtocol umbilical =
> > taskOwner.doAs(new PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
> > @Override
> > public TaskUmbilicalProtocol run() throws Exception {
> > return (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
> > TaskUmbilicalProtocol.versionID,
> > address,
> > defaultConf);
> > }
> > });
> >
> > What puzzled me is that the job id is actually passed in as the user name to task tracker. On the Name node side, when it tries to map the non-existing user name, i.e., task id, to a group, it always returns empty array. As a result, we always see annoying warning messages such as
> >
> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
> >
> > Sometimes, the warning messages were thrown so fast, hundreds or even thousands per second for a big cluster, the system performance was degraded dramatically.
> >
> > Could someone please explain why this logic was designed in this way? Any benefit to use non-existing user for the group mapping? Or is this a bug?
> >
> > Thanks in advance,
> >
> > John
>
>
> --
> CONFIDENTIALITY NOTICE
> NOTICE: This message is intended for the use of the individual or entity to
> which it is addressed and may contain information that is confidential,
> privileged and exempt from disclosure under applicable law. If the reader
> of this message is not the intended recipient, you are hereby notified that
> any printing, copying, dissemination, distribution, disclosure or
> forwarding of this communication is strictly prohibited. If you have
> received this communication in error, please contact the sender immediately
> and delete it from your system. Thank You.
-----------------------------------------
Chris Schneider
http://www.scaleunlimited.com
custom big data solutions
-----------------------------------------
Re: A question about Hadoop 1 job user id used for group mapping, which could lead to performance degradatioin
Posted by Chris Schneider <Sc...@TransPac.com>.
Hi John,
My AWS Elastic MapReduce NameNode is also filling its log file with messages like the following:
2014-02-18 23:56:52,344 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 78 on 9000): No groups available for user job_201402182309_0073
2014-02-18 23:56:52,351 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 48 on 9000): No groups available for user job_201402182309_0073
2014-02-18 23:56:52,356 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 38 on 9000): No groups available for user job_201402182309_0073
I ran into this same issue in March 2013 and got past it by using an m1.xlarge master node (instead of my usual m1.large) when (like right now) I double my slave count (to 32 cc2.8xlarge instances) to re-import a lot of my input data. Using that m1.xlarge didn't prevent the NameNode from logging messages like this, but the beefier instance seemed to weather the load these messages represented better.
Unfortunately, even my m1.xlarge master node now seems overwhelmed. The cluster starts off fine, efficiently mowing through the jobs in my job flow step for a few hours, but it eventually gets into a mode where the copy phase of the reduce jobs appear to make no progress at all. At that point, the NameNode seems to be spending all of its time writing messages like the ones above.
The issue doesn't seem to be related to the NameNode JVM size (I tried increasing it to 4GB before I realized it never used more than ~400MB), nor dfs.namenode.handler.count (which I increased from 64 to 96).
We're currently trying to work around the problem by hacking log4j.properties to set the logging level for org.apache.hadoop.security.UserGroupInformation to ERROR. We might have to do so for the entire package, as I've also seen the following in the NameNode logs:
2014-02-19 01:01:24,184 WARN org.apache.hadoop.security.ShellBasedUnixGroupsMapping (IPC Server handler 84 on 9000): got exception trying to get groups for user job_201402182309_0226
org.apache.hadoop.util.Shell$ExitCodeException: id: job_201402182309_0226: No such user
at org.apache.hadoop.util.Shell.runCommand(Shell.java:255)
at org.apache.hadoop.util.Shell.run(Shell.java:182)
at org.apache.hadoop.util.Shell$ShellCommandExecutor.execute(Shell.java:375)
at org.apache.hadoop.util.Shell.execCommand(Shell.java:461)
at org.apache.hadoop.util.Shell.execCommand(Shell.java:444)
at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getUnixGroups(ShellBasedUnixGroupsMapping.java:78)
at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getGroups(ShellBasedUnixGroupsMapping.java:53)
at org.apache.hadoop.security.Groups.getGroups(Groups.java:79)
at org.apache.hadoop.security.UserGroupInformation.getGroupNames(UserGroupInformation.java:1037)
at org.apache.hadoop.hdfs.server.namenode.FSPermissionChecker.<init>(FSPermissionChecker.java:50)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkPermission(FSNamesystem.java:5218)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkTraverse(FSNamesystem.java:5201)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getFileInfo(FSNamesystem.java:2030)
at org.apache.hadoop.hdfs.server.namenode.NameNode.getFileInfo(NameNode.java:850)
at sun.reflect.GeneratedMethodAccessor7.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:573)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1393)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1389)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:396)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1132)
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1387)
I would also be very interested in hearing Jakob Homan and Deveraj Das respond to your analysis of the changes made for MAPREDUCE-1457.
Please post again with any further information you're able to glean about this problem.
Thanks,
- Chris
On Jan 8, 2014, at 1:26 PM, Jian Fang wrote:
> Looked a bit deeper and seems this code was introduced by the following JIRA.
>
> https://issues.apache.org/jira/browse/MAPREDUCE-1457
>
> There is another related JIRA, i.e., https://issues.apache.org/jira/browse/MAPREDUCE-4329.
>
> Perhaps, the warning message is a side effect of JIRA MAPREDUCE-1457 when the cluster is running in non-secured mode. There should be some code path that caused the job id was treated as user name in task tracker or job tracker. Then the job id was passed to HDFS name node. This is definitely a big problem since the heavy warning logs alone degraded the system performance in a relatively big cluster.
>
> This behavior is very easy to reproduce by simply running terasort on a cluster.
>
> Any suggestion to fix this problem?
>
>
>
>
> On Wed, Jan 8, 2014 at 11:18 AM, Jian Fang <ji...@gmail.com> wrote:
> Thanks Vinod for your quick response. It is running in non-secure mode.
>
> I still don't get what is the purpose to use job id in UGI. Could you please explain a bit more?
>
> Thanks,
>
> John
>
>
> On Wed, Jan 8, 2014 at 10:11 AM, Vinod Kumar Vavilapalli <vi...@hortonworks.com> wrote:
> It just seems like lazy code. You can see that, later, there is this:
>
> {code}
>
> for(Token<?> token : UserGroupInformation.getCurrentUser().getTokens()) {
> childUGI.addToken(token);
> }
>
> {code}
>
> So eventually the JobToken is getting added to the UGI which runs task-code.
>
> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
>
> This seems to be a problem. When the task tries to reach the NameNode, it should do so as the user, not the job-id. It is not just logging, I'd be surprised if jobs pass. Do you have permissions enabled on HDFS?
>
> Oh, or is this in non-secure mode (i.e. without kerberos)?
>
> +Vinod
>
>
> On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com> wrote:
>
> > Hi,
> >
> > I looked at Hadoop 1.X source code and found some logic that I could not understand.
> >
> > In the org.apache.hadoop.mapred.Child class, there were two UGIs defined as follows.
> >
> > UserGroupInformation current = UserGroupInformation.getCurrentUser();
> > current.addToken(jt);
> >
> > UserGroupInformation taskOwner
> > = UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
> > taskOwner.addToken(jt);
> >
> > But it is the taskOwner that is actually passed as a UGI to task tracker and then to HDFS. The first one was not referenced any where.
> >
> > final TaskUmbilicalProtocol umbilical =
> > taskOwner.doAs(new PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
> > @Override
> > public TaskUmbilicalProtocol run() throws Exception {
> > return (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
> > TaskUmbilicalProtocol.versionID,
> > address,
> > defaultConf);
> > }
> > });
> >
> > What puzzled me is that the job id is actually passed in as the user name to task tracker. On the Name node side, when it tries to map the non-existing user name, i.e., task id, to a group, it always returns empty array. As a result, we always see annoying warning messages such as
> >
> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
> >
> > Sometimes, the warning messages were thrown so fast, hundreds or even thousands per second for a big cluster, the system performance was degraded dramatically.
> >
> > Could someone please explain why this logic was designed in this way? Any benefit to use non-existing user for the group mapping? Or is this a bug?
> >
> > Thanks in advance,
> >
> > John
>
>
> --
> CONFIDENTIALITY NOTICE
> NOTICE: This message is intended for the use of the individual or entity to
> which it is addressed and may contain information that is confidential,
> privileged and exempt from disclosure under applicable law. If the reader
> of this message is not the intended recipient, you are hereby notified that
> any printing, copying, dissemination, distribution, disclosure or
> forwarding of this communication is strictly prohibited. If you have
> received this communication in error, please contact the sender immediately
> and delete it from your system. Thank You.
-----------------------------------------
Chris Schneider
http://www.scaleunlimited.com
custom big data solutions
-----------------------------------------
Re: A question about Hadoop 1 job user id used for group mapping, which could lead to performance degradatioin
Posted by Chris Schneider <Sc...@TransPac.com>.
Hi John,
My AWS Elastic MapReduce NameNode is also filling its log file with messages like the following:
2014-02-18 23:56:52,344 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 78 on 9000): No groups available for user job_201402182309_0073
2014-02-18 23:56:52,351 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 48 on 9000): No groups available for user job_201402182309_0073
2014-02-18 23:56:52,356 WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 38 on 9000): No groups available for user job_201402182309_0073
I ran into this same issue in March 2013 and got past it by using an m1.xlarge master node (instead of my usual m1.large) when (like right now) I double my slave count (to 32 cc2.8xlarge instances) to re-import a lot of my input data. Using that m1.xlarge didn't prevent the NameNode from logging messages like this, but the beefier instance seemed to weather the load these messages represented better.
Unfortunately, even my m1.xlarge master node now seems overwhelmed. The cluster starts off fine, efficiently mowing through the jobs in my job flow step for a few hours, but it eventually gets into a mode where the copy phase of the reduce jobs appear to make no progress at all. At that point, the NameNode seems to be spending all of its time writing messages like the ones above.
The issue doesn't seem to be related to the NameNode JVM size (I tried increasing it to 4GB before I realized it never used more than ~400MB), nor dfs.namenode.handler.count (which I increased from 64 to 96).
We're currently trying to work around the problem by hacking log4j.properties to set the logging level for org.apache.hadoop.security.UserGroupInformation to ERROR. We might have to do so for the entire package, as I've also seen the following in the NameNode logs:
2014-02-19 01:01:24,184 WARN org.apache.hadoop.security.ShellBasedUnixGroupsMapping (IPC Server handler 84 on 9000): got exception trying to get groups for user job_201402182309_0226
org.apache.hadoop.util.Shell$ExitCodeException: id: job_201402182309_0226: No such user
at org.apache.hadoop.util.Shell.runCommand(Shell.java:255)
at org.apache.hadoop.util.Shell.run(Shell.java:182)
at org.apache.hadoop.util.Shell$ShellCommandExecutor.execute(Shell.java:375)
at org.apache.hadoop.util.Shell.execCommand(Shell.java:461)
at org.apache.hadoop.util.Shell.execCommand(Shell.java:444)
at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getUnixGroups(ShellBasedUnixGroupsMapping.java:78)
at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getGroups(ShellBasedUnixGroupsMapping.java:53)
at org.apache.hadoop.security.Groups.getGroups(Groups.java:79)
at org.apache.hadoop.security.UserGroupInformation.getGroupNames(UserGroupInformation.java:1037)
at org.apache.hadoop.hdfs.server.namenode.FSPermissionChecker.<init>(FSPermissionChecker.java:50)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkPermission(FSNamesystem.java:5218)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkTraverse(FSNamesystem.java:5201)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getFileInfo(FSNamesystem.java:2030)
at org.apache.hadoop.hdfs.server.namenode.NameNode.getFileInfo(NameNode.java:850)
at sun.reflect.GeneratedMethodAccessor7.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:573)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1393)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1389)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:396)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1132)
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1387)
I would also be very interested in hearing Jakob Homan and Deveraj Das respond to your analysis of the changes made for MAPREDUCE-1457.
Please post again with any further information you're able to glean about this problem.
Thanks,
- Chris
On Jan 8, 2014, at 1:26 PM, Jian Fang wrote:
> Looked a bit deeper and seems this code was introduced by the following JIRA.
>
> https://issues.apache.org/jira/browse/MAPREDUCE-1457
>
> There is another related JIRA, i.e., https://issues.apache.org/jira/browse/MAPREDUCE-4329.
>
> Perhaps, the warning message is a side effect of JIRA MAPREDUCE-1457 when the cluster is running in non-secured mode. There should be some code path that caused the job id was treated as user name in task tracker or job tracker. Then the job id was passed to HDFS name node. This is definitely a big problem since the heavy warning logs alone degraded the system performance in a relatively big cluster.
>
> This behavior is very easy to reproduce by simply running terasort on a cluster.
>
> Any suggestion to fix this problem?
>
>
>
>
> On Wed, Jan 8, 2014 at 11:18 AM, Jian Fang <ji...@gmail.com> wrote:
> Thanks Vinod for your quick response. It is running in non-secure mode.
>
> I still don't get what is the purpose to use job id in UGI. Could you please explain a bit more?
>
> Thanks,
>
> John
>
>
> On Wed, Jan 8, 2014 at 10:11 AM, Vinod Kumar Vavilapalli <vi...@hortonworks.com> wrote:
> It just seems like lazy code. You can see that, later, there is this:
>
> {code}
>
> for(Token<?> token : UserGroupInformation.getCurrentUser().getTokens()) {
> childUGI.addToken(token);
> }
>
> {code}
>
> So eventually the JobToken is getting added to the UGI which runs task-code.
>
> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
>
> This seems to be a problem. When the task tries to reach the NameNode, it should do so as the user, not the job-id. It is not just logging, I'd be surprised if jobs pass. Do you have permissions enabled on HDFS?
>
> Oh, or is this in non-secure mode (i.e. without kerberos)?
>
> +Vinod
>
>
> On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com> wrote:
>
> > Hi,
> >
> > I looked at Hadoop 1.X source code and found some logic that I could not understand.
> >
> > In the org.apache.hadoop.mapred.Child class, there were two UGIs defined as follows.
> >
> > UserGroupInformation current = UserGroupInformation.getCurrentUser();
> > current.addToken(jt);
> >
> > UserGroupInformation taskOwner
> > = UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
> > taskOwner.addToken(jt);
> >
> > But it is the taskOwner that is actually passed as a UGI to task tracker and then to HDFS. The first one was not referenced any where.
> >
> > final TaskUmbilicalProtocol umbilical =
> > taskOwner.doAs(new PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
> > @Override
> > public TaskUmbilicalProtocol run() throws Exception {
> > return (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
> > TaskUmbilicalProtocol.versionID,
> > address,
> > defaultConf);
> > }
> > });
> >
> > What puzzled me is that the job id is actually passed in as the user name to task tracker. On the Name node side, when it tries to map the non-existing user name, i.e., task id, to a group, it always returns empty array. As a result, we always see annoying warning messages such as
> >
> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
> >
> > Sometimes, the warning messages were thrown so fast, hundreds or even thousands per second for a big cluster, the system performance was degraded dramatically.
> >
> > Could someone please explain why this logic was designed in this way? Any benefit to use non-existing user for the group mapping? Or is this a bug?
> >
> > Thanks in advance,
> >
> > John
>
>
> --
> CONFIDENTIALITY NOTICE
> NOTICE: This message is intended for the use of the individual or entity to
> which it is addressed and may contain information that is confidential,
> privileged and exempt from disclosure under applicable law. If the reader
> of this message is not the intended recipient, you are hereby notified that
> any printing, copying, dissemination, distribution, disclosure or
> forwarding of this communication is strictly prohibited. If you have
> received this communication in error, please contact the sender immediately
> and delete it from your system. Thank You.
-----------------------------------------
Chris Schneider
http://www.scaleunlimited.com
custom big data solutions
-----------------------------------------
Re: A question about Hadoop 1 job user id used for group mapping,
which could lead to performance degradatioin
Posted by Jian Fang <ji...@gmail.com>.
Looked a bit deeper and seems this code was introduced by the following
JIRA.
https://issues.apache.org/jira/browse/MAPREDUCE-1457
There is another related JIRA, i.e.,
https://issues.apache.org/jira/browse/MAPREDUCE-4329.
Perhaps, the warning message is a side effect of JIRA MAPREDUCE-1457 when
the cluster is running in non-secured mode. There should be some code path
that caused the job id was treated as user name in task tracker or job
tracker. Then the job id was passed to HDFS name node. This is definitely a
big problem since the heavy warning logs alone degraded the system
performance in a relatively big cluster.
This behavior is very easy to reproduce by simply running terasort on a
cluster.
Any suggestion to fix this problem?
On Wed, Jan 8, 2014 at 11:18 AM, Jian Fang <ji...@gmail.com>wrote:
> Thanks Vinod for your quick response. It is running in non-secure mode.
>
> I still don't get what is the purpose to use job id in UGI. Could you
> please explain a bit more?
>
> Thanks,
>
> John
>
>
> On Wed, Jan 8, 2014 at 10:11 AM, Vinod Kumar Vavilapalli <
> vinodkv@hortonworks.com> wrote:
>
>> It just seems like lazy code. You can see that, later, there is this:
>>
>> {code}
>>
>> for(Token<?> token :
>> UserGroupInformation.getCurrentUser().getTokens()) {
>> childUGI.addToken(token);
>> }
>>
>> {code}
>>
>> So eventually the JobToken is getting added to the UGI which runs
>> task-code.
>>
>> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server
>> handler 63 on 9000): No groups available for user job_201401071758_0002
>>
>> This seems to be a problem. When the task tries to reach the NameNode, it
>> should do so as the user, not the job-id. It is not just logging, I'd be
>> surprised if jobs pass. Do you have permissions enabled on HDFS?
>>
>> Oh, or is this in non-secure mode (i.e. without kerberos)?
>>
>> +Vinod
>>
>>
>> On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com>
>> wrote:
>>
>> > Hi,
>> >
>> > I looked at Hadoop 1.X source code and found some logic that I could
>> not understand.
>> >
>> > In the org.apache.hadoop.mapred.Child class, there were two UGIs
>> defined as follows.
>> >
>> > UserGroupInformation current =
>> UserGroupInformation.getCurrentUser();
>> > current.addToken(jt);
>> >
>> > UserGroupInformation taskOwner
>> > =
>> UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
>> > taskOwner.addToken(jt);
>> >
>> > But it is the taskOwner that is actually passed as a UGI to task
>> tracker and then to HDFS. The first one was not referenced any where.
>> >
>> > final TaskUmbilicalProtocol umbilical =
>> > taskOwner.doAs(new
>> PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
>> > @Override
>> > public TaskUmbilicalProtocol run() throws Exception {
>> > return
>> (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
>> > TaskUmbilicalProtocol.versionID,
>> > address,
>> > defaultConf);
>> > }
>> > });
>> >
>> > What puzzled me is that the job id is actually passed in as the user
>> name to task tracker. On the Name node side, when it tries to map the
>> non-existing user name, i.e., task id, to a group, it always returns empty
>> array. As a result, we always see annoying warning messages such as
>> >
>> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server
>> handler 63 on 9000): No groups available for user job_201401071758_0002
>> >
>> > Sometimes, the warning messages were thrown so fast, hundreds or even
>> thousands per second for a big cluster, the system performance was degraded
>> dramatically.
>> >
>> > Could someone please explain why this logic was designed in this way?
>> Any benefit to use non-existing user for the group mapping? Or is this a
>> bug?
>> >
>> > Thanks in advance,
>> >
>> > John
>>
>>
>> --
>> CONFIDENTIALITY NOTICE
>> NOTICE: This message is intended for the use of the individual or entity
>> to
>> which it is addressed and may contain information that is confidential,
>> privileged and exempt from disclosure under applicable law. If the reader
>> of this message is not the intended recipient, you are hereby notified
>> that
>> any printing, copying, dissemination, distribution, disclosure or
>> forwarding of this communication is strictly prohibited. If you have
>> received this communication in error, please contact the sender
>> immediately
>> and delete it from your system. Thank You.
>>
>
>
Re: A question about Hadoop 1 job user id used for group mapping,
which could lead to performance degradatioin
Posted by Jian Fang <ji...@gmail.com>.
Looked a bit deeper and seems this code was introduced by the following
JIRA.
https://issues.apache.org/jira/browse/MAPREDUCE-1457
There is another related JIRA, i.e.,
https://issues.apache.org/jira/browse/MAPREDUCE-4329.
Perhaps, the warning message is a side effect of JIRA MAPREDUCE-1457 when
the cluster is running in non-secured mode. There should be some code path
that caused the job id was treated as user name in task tracker or job
tracker. Then the job id was passed to HDFS name node. This is definitely a
big problem since the heavy warning logs alone degraded the system
performance in a relatively big cluster.
This behavior is very easy to reproduce by simply running terasort on a
cluster.
Any suggestion to fix this problem?
On Wed, Jan 8, 2014 at 11:18 AM, Jian Fang <ji...@gmail.com>wrote:
> Thanks Vinod for your quick response. It is running in non-secure mode.
>
> I still don't get what is the purpose to use job id in UGI. Could you
> please explain a bit more?
>
> Thanks,
>
> John
>
>
> On Wed, Jan 8, 2014 at 10:11 AM, Vinod Kumar Vavilapalli <
> vinodkv@hortonworks.com> wrote:
>
>> It just seems like lazy code. You can see that, later, there is this:
>>
>> {code}
>>
>> for(Token<?> token :
>> UserGroupInformation.getCurrentUser().getTokens()) {
>> childUGI.addToken(token);
>> }
>>
>> {code}
>>
>> So eventually the JobToken is getting added to the UGI which runs
>> task-code.
>>
>> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server
>> handler 63 on 9000): No groups available for user job_201401071758_0002
>>
>> This seems to be a problem. When the task tries to reach the NameNode, it
>> should do so as the user, not the job-id. It is not just logging, I'd be
>> surprised if jobs pass. Do you have permissions enabled on HDFS?
>>
>> Oh, or is this in non-secure mode (i.e. without kerberos)?
>>
>> +Vinod
>>
>>
>> On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com>
>> wrote:
>>
>> > Hi,
>> >
>> > I looked at Hadoop 1.X source code and found some logic that I could
>> not understand.
>> >
>> > In the org.apache.hadoop.mapred.Child class, there were two UGIs
>> defined as follows.
>> >
>> > UserGroupInformation current =
>> UserGroupInformation.getCurrentUser();
>> > current.addToken(jt);
>> >
>> > UserGroupInformation taskOwner
>> > =
>> UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
>> > taskOwner.addToken(jt);
>> >
>> > But it is the taskOwner that is actually passed as a UGI to task
>> tracker and then to HDFS. The first one was not referenced any where.
>> >
>> > final TaskUmbilicalProtocol umbilical =
>> > taskOwner.doAs(new
>> PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
>> > @Override
>> > public TaskUmbilicalProtocol run() throws Exception {
>> > return
>> (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
>> > TaskUmbilicalProtocol.versionID,
>> > address,
>> > defaultConf);
>> > }
>> > });
>> >
>> > What puzzled me is that the job id is actually passed in as the user
>> name to task tracker. On the Name node side, when it tries to map the
>> non-existing user name, i.e., task id, to a group, it always returns empty
>> array. As a result, we always see annoying warning messages such as
>> >
>> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server
>> handler 63 on 9000): No groups available for user job_201401071758_0002
>> >
>> > Sometimes, the warning messages were thrown so fast, hundreds or even
>> thousands per second for a big cluster, the system performance was degraded
>> dramatically.
>> >
>> > Could someone please explain why this logic was designed in this way?
>> Any benefit to use non-existing user for the group mapping? Or is this a
>> bug?
>> >
>> > Thanks in advance,
>> >
>> > John
>>
>>
>> --
>> CONFIDENTIALITY NOTICE
>> NOTICE: This message is intended for the use of the individual or entity
>> to
>> which it is addressed and may contain information that is confidential,
>> privileged and exempt from disclosure under applicable law. If the reader
>> of this message is not the intended recipient, you are hereby notified
>> that
>> any printing, copying, dissemination, distribution, disclosure or
>> forwarding of this communication is strictly prohibited. If you have
>> received this communication in error, please contact the sender
>> immediately
>> and delete it from your system. Thank You.
>>
>
>
Re: A question about Hadoop 1 job user id used for group mapping,
which could lead to performance degradatioin
Posted by Jian Fang <ji...@gmail.com>.
Looked a bit deeper and seems this code was introduced by the following
JIRA.
https://issues.apache.org/jira/browse/MAPREDUCE-1457
There is another related JIRA, i.e.,
https://issues.apache.org/jira/browse/MAPREDUCE-4329.
Perhaps, the warning message is a side effect of JIRA MAPREDUCE-1457 when
the cluster is running in non-secured mode. There should be some code path
that caused the job id was treated as user name in task tracker or job
tracker. Then the job id was passed to HDFS name node. This is definitely a
big problem since the heavy warning logs alone degraded the system
performance in a relatively big cluster.
This behavior is very easy to reproduce by simply running terasort on a
cluster.
Any suggestion to fix this problem?
On Wed, Jan 8, 2014 at 11:18 AM, Jian Fang <ji...@gmail.com>wrote:
> Thanks Vinod for your quick response. It is running in non-secure mode.
>
> I still don't get what is the purpose to use job id in UGI. Could you
> please explain a bit more?
>
> Thanks,
>
> John
>
>
> On Wed, Jan 8, 2014 at 10:11 AM, Vinod Kumar Vavilapalli <
> vinodkv@hortonworks.com> wrote:
>
>> It just seems like lazy code. You can see that, later, there is this:
>>
>> {code}
>>
>> for(Token<?> token :
>> UserGroupInformation.getCurrentUser().getTokens()) {
>> childUGI.addToken(token);
>> }
>>
>> {code}
>>
>> So eventually the JobToken is getting added to the UGI which runs
>> task-code.
>>
>> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server
>> handler 63 on 9000): No groups available for user job_201401071758_0002
>>
>> This seems to be a problem. When the task tries to reach the NameNode, it
>> should do so as the user, not the job-id. It is not just logging, I'd be
>> surprised if jobs pass. Do you have permissions enabled on HDFS?
>>
>> Oh, or is this in non-secure mode (i.e. without kerberos)?
>>
>> +Vinod
>>
>>
>> On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com>
>> wrote:
>>
>> > Hi,
>> >
>> > I looked at Hadoop 1.X source code and found some logic that I could
>> not understand.
>> >
>> > In the org.apache.hadoop.mapred.Child class, there were two UGIs
>> defined as follows.
>> >
>> > UserGroupInformation current =
>> UserGroupInformation.getCurrentUser();
>> > current.addToken(jt);
>> >
>> > UserGroupInformation taskOwner
>> > =
>> UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
>> > taskOwner.addToken(jt);
>> >
>> > But it is the taskOwner that is actually passed as a UGI to task
>> tracker and then to HDFS. The first one was not referenced any where.
>> >
>> > final TaskUmbilicalProtocol umbilical =
>> > taskOwner.doAs(new
>> PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
>> > @Override
>> > public TaskUmbilicalProtocol run() throws Exception {
>> > return
>> (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
>> > TaskUmbilicalProtocol.versionID,
>> > address,
>> > defaultConf);
>> > }
>> > });
>> >
>> > What puzzled me is that the job id is actually passed in as the user
>> name to task tracker. On the Name node side, when it tries to map the
>> non-existing user name, i.e., task id, to a group, it always returns empty
>> array. As a result, we always see annoying warning messages such as
>> >
>> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server
>> handler 63 on 9000): No groups available for user job_201401071758_0002
>> >
>> > Sometimes, the warning messages were thrown so fast, hundreds or even
>> thousands per second for a big cluster, the system performance was degraded
>> dramatically.
>> >
>> > Could someone please explain why this logic was designed in this way?
>> Any benefit to use non-existing user for the group mapping? Or is this a
>> bug?
>> >
>> > Thanks in advance,
>> >
>> > John
>>
>>
>> --
>> CONFIDENTIALITY NOTICE
>> NOTICE: This message is intended for the use of the individual or entity
>> to
>> which it is addressed and may contain information that is confidential,
>> privileged and exempt from disclosure under applicable law. If the reader
>> of this message is not the intended recipient, you are hereby notified
>> that
>> any printing, copying, dissemination, distribution, disclosure or
>> forwarding of this communication is strictly prohibited. If you have
>> received this communication in error, please contact the sender
>> immediately
>> and delete it from your system. Thank You.
>>
>
>
Re: A question about Hadoop 1 job user id used for group mapping,
which could lead to performance degradatioin
Posted by Jian Fang <ji...@gmail.com>.
Looked a bit deeper and seems this code was introduced by the following
JIRA.
https://issues.apache.org/jira/browse/MAPREDUCE-1457
There is another related JIRA, i.e.,
https://issues.apache.org/jira/browse/MAPREDUCE-4329.
Perhaps, the warning message is a side effect of JIRA MAPREDUCE-1457 when
the cluster is running in non-secured mode. There should be some code path
that caused the job id was treated as user name in task tracker or job
tracker. Then the job id was passed to HDFS name node. This is definitely a
big problem since the heavy warning logs alone degraded the system
performance in a relatively big cluster.
This behavior is very easy to reproduce by simply running terasort on a
cluster.
Any suggestion to fix this problem?
On Wed, Jan 8, 2014 at 11:18 AM, Jian Fang <ji...@gmail.com>wrote:
> Thanks Vinod for your quick response. It is running in non-secure mode.
>
> I still don't get what is the purpose to use job id in UGI. Could you
> please explain a bit more?
>
> Thanks,
>
> John
>
>
> On Wed, Jan 8, 2014 at 10:11 AM, Vinod Kumar Vavilapalli <
> vinodkv@hortonworks.com> wrote:
>
>> It just seems like lazy code. You can see that, later, there is this:
>>
>> {code}
>>
>> for(Token<?> token :
>> UserGroupInformation.getCurrentUser().getTokens()) {
>> childUGI.addToken(token);
>> }
>>
>> {code}
>>
>> So eventually the JobToken is getting added to the UGI which runs
>> task-code.
>>
>> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server
>> handler 63 on 9000): No groups available for user job_201401071758_0002
>>
>> This seems to be a problem. When the task tries to reach the NameNode, it
>> should do so as the user, not the job-id. It is not just logging, I'd be
>> surprised if jobs pass. Do you have permissions enabled on HDFS?
>>
>> Oh, or is this in non-secure mode (i.e. without kerberos)?
>>
>> +Vinod
>>
>>
>> On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com>
>> wrote:
>>
>> > Hi,
>> >
>> > I looked at Hadoop 1.X source code and found some logic that I could
>> not understand.
>> >
>> > In the org.apache.hadoop.mapred.Child class, there were two UGIs
>> defined as follows.
>> >
>> > UserGroupInformation current =
>> UserGroupInformation.getCurrentUser();
>> > current.addToken(jt);
>> >
>> > UserGroupInformation taskOwner
>> > =
>> UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
>> > taskOwner.addToken(jt);
>> >
>> > But it is the taskOwner that is actually passed as a UGI to task
>> tracker and then to HDFS. The first one was not referenced any where.
>> >
>> > final TaskUmbilicalProtocol umbilical =
>> > taskOwner.doAs(new
>> PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
>> > @Override
>> > public TaskUmbilicalProtocol run() throws Exception {
>> > return
>> (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
>> > TaskUmbilicalProtocol.versionID,
>> > address,
>> > defaultConf);
>> > }
>> > });
>> >
>> > What puzzled me is that the job id is actually passed in as the user
>> name to task tracker. On the Name node side, when it tries to map the
>> non-existing user name, i.e., task id, to a group, it always returns empty
>> array. As a result, we always see annoying warning messages such as
>> >
>> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server
>> handler 63 on 9000): No groups available for user job_201401071758_0002
>> >
>> > Sometimes, the warning messages were thrown so fast, hundreds or even
>> thousands per second for a big cluster, the system performance was degraded
>> dramatically.
>> >
>> > Could someone please explain why this logic was designed in this way?
>> Any benefit to use non-existing user for the group mapping? Or is this a
>> bug?
>> >
>> > Thanks in advance,
>> >
>> > John
>>
>>
>> --
>> CONFIDENTIALITY NOTICE
>> NOTICE: This message is intended for the use of the individual or entity
>> to
>> which it is addressed and may contain information that is confidential,
>> privileged and exempt from disclosure under applicable law. If the reader
>> of this message is not the intended recipient, you are hereby notified
>> that
>> any printing, copying, dissemination, distribution, disclosure or
>> forwarding of this communication is strictly prohibited. If you have
>> received this communication in error, please contact the sender
>> immediately
>> and delete it from your system. Thank You.
>>
>
>
Re: A question about Hadoop 1 job user id used for group mapping,
which could lead to performance degradatioin
Posted by Jian Fang <ji...@gmail.com>.
Thanks Vinod for your quick response. It is running in non-secure mode.
I still don't get what is the purpose to use job id in UGI. Could you
please explain a bit more?
Thanks,
John
On Wed, Jan 8, 2014 at 10:11 AM, Vinod Kumar Vavilapalli <
vinodkv@hortonworks.com> wrote:
> It just seems like lazy code. You can see that, later, there is this:
>
> {code}
>
> for(Token<?> token :
> UserGroupInformation.getCurrentUser().getTokens()) {
> childUGI.addToken(token);
> }
>
> {code}
>
> So eventually the JobToken is getting added to the UGI which runs
> task-code.
>
> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server
> handler 63 on 9000): No groups available for user job_201401071758_0002
>
> This seems to be a problem. When the task tries to reach the NameNode, it
> should do so as the user, not the job-id. It is not just logging, I'd be
> surprised if jobs pass. Do you have permissions enabled on HDFS?
>
> Oh, or is this in non-secure mode (i.e. without kerberos)?
>
> +Vinod
>
>
> On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com>
> wrote:
>
> > Hi,
> >
> > I looked at Hadoop 1.X source code and found some logic that I could not
> understand.
> >
> > In the org.apache.hadoop.mapred.Child class, there were two UGIs defined
> as follows.
> >
> > UserGroupInformation current = UserGroupInformation.getCurrentUser();
> > current.addToken(jt);
> >
> > UserGroupInformation taskOwner
> > =
> UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
> > taskOwner.addToken(jt);
> >
> > But it is the taskOwner that is actually passed as a UGI to task tracker
> and then to HDFS. The first one was not referenced any where.
> >
> > final TaskUmbilicalProtocol umbilical =
> > taskOwner.doAs(new
> PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
> > @Override
> > public TaskUmbilicalProtocol run() throws Exception {
> > return
> (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
> > TaskUmbilicalProtocol.versionID,
> > address,
> > defaultConf);
> > }
> > });
> >
> > What puzzled me is that the job id is actually passed in as the user
> name to task tracker. On the Name node side, when it tries to map the
> non-existing user name, i.e., task id, to a group, it always returns empty
> array. As a result, we always see annoying warning messages such as
> >
> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server
> handler 63 on 9000): No groups available for user job_201401071758_0002
> >
> > Sometimes, the warning messages were thrown so fast, hundreds or even
> thousands per second for a big cluster, the system performance was degraded
> dramatically.
> >
> > Could someone please explain why this logic was designed in this way?
> Any benefit to use non-existing user for the group mapping? Or is this a
> bug?
> >
> > Thanks in advance,
> >
> > John
>
>
> --
> CONFIDENTIALITY NOTICE
> NOTICE: This message is intended for the use of the individual or entity to
> which it is addressed and may contain information that is confidential,
> privileged and exempt from disclosure under applicable law. If the reader
> of this message is not the intended recipient, you are hereby notified that
> any printing, copying, dissemination, distribution, disclosure or
> forwarding of this communication is strictly prohibited. If you have
> received this communication in error, please contact the sender immediately
> and delete it from your system. Thank You.
>
Re: A question about Hadoop 1 job user id used for group mapping,
which could lead to performance degradatioin
Posted by Jian Fang <ji...@gmail.com>.
Thanks Vinod for your quick response. It is running in non-secure mode.
I still don't get what is the purpose to use job id in UGI. Could you
please explain a bit more?
Thanks,
John
On Wed, Jan 8, 2014 at 10:11 AM, Vinod Kumar Vavilapalli <
vinodkv@hortonworks.com> wrote:
> It just seems like lazy code. You can see that, later, there is this:
>
> {code}
>
> for(Token<?> token :
> UserGroupInformation.getCurrentUser().getTokens()) {
> childUGI.addToken(token);
> }
>
> {code}
>
> So eventually the JobToken is getting added to the UGI which runs
> task-code.
>
> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server
> handler 63 on 9000): No groups available for user job_201401071758_0002
>
> This seems to be a problem. When the task tries to reach the NameNode, it
> should do so as the user, not the job-id. It is not just logging, I'd be
> surprised if jobs pass. Do you have permissions enabled on HDFS?
>
> Oh, or is this in non-secure mode (i.e. without kerberos)?
>
> +Vinod
>
>
> On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com>
> wrote:
>
> > Hi,
> >
> > I looked at Hadoop 1.X source code and found some logic that I could not
> understand.
> >
> > In the org.apache.hadoop.mapred.Child class, there were two UGIs defined
> as follows.
> >
> > UserGroupInformation current = UserGroupInformation.getCurrentUser();
> > current.addToken(jt);
> >
> > UserGroupInformation taskOwner
> > =
> UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
> > taskOwner.addToken(jt);
> >
> > But it is the taskOwner that is actually passed as a UGI to task tracker
> and then to HDFS. The first one was not referenced any where.
> >
> > final TaskUmbilicalProtocol umbilical =
> > taskOwner.doAs(new
> PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
> > @Override
> > public TaskUmbilicalProtocol run() throws Exception {
> > return
> (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
> > TaskUmbilicalProtocol.versionID,
> > address,
> > defaultConf);
> > }
> > });
> >
> > What puzzled me is that the job id is actually passed in as the user
> name to task tracker. On the Name node side, when it tries to map the
> non-existing user name, i.e., task id, to a group, it always returns empty
> array. As a result, we always see annoying warning messages such as
> >
> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server
> handler 63 on 9000): No groups available for user job_201401071758_0002
> >
> > Sometimes, the warning messages were thrown so fast, hundreds or even
> thousands per second for a big cluster, the system performance was degraded
> dramatically.
> >
> > Could someone please explain why this logic was designed in this way?
> Any benefit to use non-existing user for the group mapping? Or is this a
> bug?
> >
> > Thanks in advance,
> >
> > John
>
>
> --
> CONFIDENTIALITY NOTICE
> NOTICE: This message is intended for the use of the individual or entity to
> which it is addressed and may contain information that is confidential,
> privileged and exempt from disclosure under applicable law. If the reader
> of this message is not the intended recipient, you are hereby notified that
> any printing, copying, dissemination, distribution, disclosure or
> forwarding of this communication is strictly prohibited. If you have
> received this communication in error, please contact the sender immediately
> and delete it from your system. Thank You.
>
Re: A question about Hadoop 1 job user id used for group mapping,
which could lead to performance degradatioin
Posted by Jian Fang <ji...@gmail.com>.
Thanks Vinod for your quick response. It is running in non-secure mode.
I still don't get what is the purpose to use job id in UGI. Could you
please explain a bit more?
Thanks,
John
On Wed, Jan 8, 2014 at 10:11 AM, Vinod Kumar Vavilapalli <
vinodkv@hortonworks.com> wrote:
> It just seems like lazy code. You can see that, later, there is this:
>
> {code}
>
> for(Token<?> token :
> UserGroupInformation.getCurrentUser().getTokens()) {
> childUGI.addToken(token);
> }
>
> {code}
>
> So eventually the JobToken is getting added to the UGI which runs
> task-code.
>
> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server
> handler 63 on 9000): No groups available for user job_201401071758_0002
>
> This seems to be a problem. When the task tries to reach the NameNode, it
> should do so as the user, not the job-id. It is not just logging, I'd be
> surprised if jobs pass. Do you have permissions enabled on HDFS?
>
> Oh, or is this in non-secure mode (i.e. without kerberos)?
>
> +Vinod
>
>
> On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com>
> wrote:
>
> > Hi,
> >
> > I looked at Hadoop 1.X source code and found some logic that I could not
> understand.
> >
> > In the org.apache.hadoop.mapred.Child class, there were two UGIs defined
> as follows.
> >
> > UserGroupInformation current = UserGroupInformation.getCurrentUser();
> > current.addToken(jt);
> >
> > UserGroupInformation taskOwner
> > =
> UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
> > taskOwner.addToken(jt);
> >
> > But it is the taskOwner that is actually passed as a UGI to task tracker
> and then to HDFS. The first one was not referenced any where.
> >
> > final TaskUmbilicalProtocol umbilical =
> > taskOwner.doAs(new
> PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
> > @Override
> > public TaskUmbilicalProtocol run() throws Exception {
> > return
> (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
> > TaskUmbilicalProtocol.versionID,
> > address,
> > defaultConf);
> > }
> > });
> >
> > What puzzled me is that the job id is actually passed in as the user
> name to task tracker. On the Name node side, when it tries to map the
> non-existing user name, i.e., task id, to a group, it always returns empty
> array. As a result, we always see annoying warning messages such as
> >
> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server
> handler 63 on 9000): No groups available for user job_201401071758_0002
> >
> > Sometimes, the warning messages were thrown so fast, hundreds or even
> thousands per second for a big cluster, the system performance was degraded
> dramatically.
> >
> > Could someone please explain why this logic was designed in this way?
> Any benefit to use non-existing user for the group mapping? Or is this a
> bug?
> >
> > Thanks in advance,
> >
> > John
>
>
> --
> CONFIDENTIALITY NOTICE
> NOTICE: This message is intended for the use of the individual or entity to
> which it is addressed and may contain information that is confidential,
> privileged and exempt from disclosure under applicable law. If the reader
> of this message is not the intended recipient, you are hereby notified that
> any printing, copying, dissemination, distribution, disclosure or
> forwarding of this communication is strictly prohibited. If you have
> received this communication in error, please contact the sender immediately
> and delete it from your system. Thank You.
>
Re: A question about Hadoop 1 job user id used for group mapping,
which could lead to performance degradatioin
Posted by Jian Fang <ji...@gmail.com>.
Thanks Vinod for your quick response. It is running in non-secure mode.
I still don't get what is the purpose to use job id in UGI. Could you
please explain a bit more?
Thanks,
John
On Wed, Jan 8, 2014 at 10:11 AM, Vinod Kumar Vavilapalli <
vinodkv@hortonworks.com> wrote:
> It just seems like lazy code. You can see that, later, there is this:
>
> {code}
>
> for(Token<?> token :
> UserGroupInformation.getCurrentUser().getTokens()) {
> childUGI.addToken(token);
> }
>
> {code}
>
> So eventually the JobToken is getting added to the UGI which runs
> task-code.
>
> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server
> handler 63 on 9000): No groups available for user job_201401071758_0002
>
> This seems to be a problem. When the task tries to reach the NameNode, it
> should do so as the user, not the job-id. It is not just logging, I'd be
> surprised if jobs pass. Do you have permissions enabled on HDFS?
>
> Oh, or is this in non-secure mode (i.e. without kerberos)?
>
> +Vinod
>
>
> On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com>
> wrote:
>
> > Hi,
> >
> > I looked at Hadoop 1.X source code and found some logic that I could not
> understand.
> >
> > In the org.apache.hadoop.mapred.Child class, there were two UGIs defined
> as follows.
> >
> > UserGroupInformation current = UserGroupInformation.getCurrentUser();
> > current.addToken(jt);
> >
> > UserGroupInformation taskOwner
> > =
> UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
> > taskOwner.addToken(jt);
> >
> > But it is the taskOwner that is actually passed as a UGI to task tracker
> and then to HDFS. The first one was not referenced any where.
> >
> > final TaskUmbilicalProtocol umbilical =
> > taskOwner.doAs(new
> PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
> > @Override
> > public TaskUmbilicalProtocol run() throws Exception {
> > return
> (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
> > TaskUmbilicalProtocol.versionID,
> > address,
> > defaultConf);
> > }
> > });
> >
> > What puzzled me is that the job id is actually passed in as the user
> name to task tracker. On the Name node side, when it tries to map the
> non-existing user name, i.e., task id, to a group, it always returns empty
> array. As a result, we always see annoying warning messages such as
> >
> > WARN org.apache.hadoop.security.UserGroupInformation (IPC Server
> handler 63 on 9000): No groups available for user job_201401071758_0002
> >
> > Sometimes, the warning messages were thrown so fast, hundreds or even
> thousands per second for a big cluster, the system performance was degraded
> dramatically.
> >
> > Could someone please explain why this logic was designed in this way?
> Any benefit to use non-existing user for the group mapping? Or is this a
> bug?
> >
> > Thanks in advance,
> >
> > John
>
>
> --
> CONFIDENTIALITY NOTICE
> NOTICE: This message is intended for the use of the individual or entity to
> which it is addressed and may contain information that is confidential,
> privileged and exempt from disclosure under applicable law. If the reader
> of this message is not the intended recipient, you are hereby notified that
> any printing, copying, dissemination, distribution, disclosure or
> forwarding of this communication is strictly prohibited. If you have
> received this communication in error, please contact the sender immediately
> and delete it from your system. Thank You.
>
Re: A question about Hadoop 1 job user id used for group mapping, which could lead to performance degradatioin
Posted by Vinod Kumar Vavilapalli <vi...@hortonworks.com>.
It just seems like lazy code. You can see that, later, there is this:
{code}
for(Token<?> token : UserGroupInformation.getCurrentUser().getTokens()) {
childUGI.addToken(token);
}
{code}
So eventually the JobToken is getting added to the UGI which runs task-code.
> WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
This seems to be a problem. When the task tries to reach the NameNode, it should do so as the user, not the job-id. It is not just logging, I'd be surprised if jobs pass. Do you have permissions enabled on HDFS?
Oh, or is this in non-secure mode (i.e. without kerberos)?
+Vinod
On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com> wrote:
> Hi,
>
> I looked at Hadoop 1.X source code and found some logic that I could not understand.
>
> In the org.apache.hadoop.mapred.Child class, there were two UGIs defined as follows.
>
> UserGroupInformation current = UserGroupInformation.getCurrentUser();
> current.addToken(jt);
>
> UserGroupInformation taskOwner
> = UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
> taskOwner.addToken(jt);
>
> But it is the taskOwner that is actually passed as a UGI to task tracker and then to HDFS. The first one was not referenced any where.
>
> final TaskUmbilicalProtocol umbilical =
> taskOwner.doAs(new PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
> @Override
> public TaskUmbilicalProtocol run() throws Exception {
> return (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
> TaskUmbilicalProtocol.versionID,
> address,
> defaultConf);
> }
> });
>
> What puzzled me is that the job id is actually passed in as the user name to task tracker. On the Name node side, when it tries to map the non-existing user name, i.e., task id, to a group, it always returns empty array. As a result, we always see annoying warning messages such as
>
> WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
>
> Sometimes, the warning messages were thrown so fast, hundreds or even thousands per second for a big cluster, the system performance was degraded dramatically.
>
> Could someone please explain why this logic was designed in this way? Any benefit to use non-existing user for the group mapping? Or is this a bug?
>
> Thanks in advance,
>
> John
--
CONFIDENTIALITY NOTICE
NOTICE: This message is intended for the use of the individual or entity to
which it is addressed and may contain information that is confidential,
privileged and exempt from disclosure under applicable law. If the reader
of this message is not the intended recipient, you are hereby notified that
any printing, copying, dissemination, distribution, disclosure or
forwarding of this communication is strictly prohibited. If you have
received this communication in error, please contact the sender immediately
and delete it from your system. Thank You.
Re: A question about Hadoop 1 job user id used for group mapping, which could lead to performance degradatioin
Posted by Vinod Kumar Vavilapalli <vi...@hortonworks.com>.
It just seems like lazy code. You can see that, later, there is this:
{code}
for(Token<?> token : UserGroupInformation.getCurrentUser().getTokens()) {
childUGI.addToken(token);
}
{code}
So eventually the JobToken is getting added to the UGI which runs task-code.
> WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
This seems to be a problem. When the task tries to reach the NameNode, it should do so as the user, not the job-id. It is not just logging, I'd be surprised if jobs pass. Do you have permissions enabled on HDFS?
Oh, or is this in non-secure mode (i.e. without kerberos)?
+Vinod
On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com> wrote:
> Hi,
>
> I looked at Hadoop 1.X source code and found some logic that I could not understand.
>
> In the org.apache.hadoop.mapred.Child class, there were two UGIs defined as follows.
>
> UserGroupInformation current = UserGroupInformation.getCurrentUser();
> current.addToken(jt);
>
> UserGroupInformation taskOwner
> = UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
> taskOwner.addToken(jt);
>
> But it is the taskOwner that is actually passed as a UGI to task tracker and then to HDFS. The first one was not referenced any where.
>
> final TaskUmbilicalProtocol umbilical =
> taskOwner.doAs(new PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
> @Override
> public TaskUmbilicalProtocol run() throws Exception {
> return (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
> TaskUmbilicalProtocol.versionID,
> address,
> defaultConf);
> }
> });
>
> What puzzled me is that the job id is actually passed in as the user name to task tracker. On the Name node side, when it tries to map the non-existing user name, i.e., task id, to a group, it always returns empty array. As a result, we always see annoying warning messages such as
>
> WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
>
> Sometimes, the warning messages were thrown so fast, hundreds or even thousands per second for a big cluster, the system performance was degraded dramatically.
>
> Could someone please explain why this logic was designed in this way? Any benefit to use non-existing user for the group mapping? Or is this a bug?
>
> Thanks in advance,
>
> John
--
CONFIDENTIALITY NOTICE
NOTICE: This message is intended for the use of the individual or entity to
which it is addressed and may contain information that is confidential,
privileged and exempt from disclosure under applicable law. If the reader
of this message is not the intended recipient, you are hereby notified that
any printing, copying, dissemination, distribution, disclosure or
forwarding of this communication is strictly prohibited. If you have
received this communication in error, please contact the sender immediately
and delete it from your system. Thank You.
Re: A question about Hadoop 1 job user id used for group mapping, which could lead to performance degradatioin
Posted by Vinod Kumar Vavilapalli <vi...@hortonworks.com>.
It just seems like lazy code. You can see that, later, there is this:
{code}
for(Token<?> token : UserGroupInformation.getCurrentUser().getTokens()) {
childUGI.addToken(token);
}
{code}
So eventually the JobToken is getting added to the UGI which runs task-code.
> WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
This seems to be a problem. When the task tries to reach the NameNode, it should do so as the user, not the job-id. It is not just logging, I'd be surprised if jobs pass. Do you have permissions enabled on HDFS?
Oh, or is this in non-secure mode (i.e. without kerberos)?
+Vinod
On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com> wrote:
> Hi,
>
> I looked at Hadoop 1.X source code and found some logic that I could not understand.
>
> In the org.apache.hadoop.mapred.Child class, there were two UGIs defined as follows.
>
> UserGroupInformation current = UserGroupInformation.getCurrentUser();
> current.addToken(jt);
>
> UserGroupInformation taskOwner
> = UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
> taskOwner.addToken(jt);
>
> But it is the taskOwner that is actually passed as a UGI to task tracker and then to HDFS. The first one was not referenced any where.
>
> final TaskUmbilicalProtocol umbilical =
> taskOwner.doAs(new PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
> @Override
> public TaskUmbilicalProtocol run() throws Exception {
> return (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
> TaskUmbilicalProtocol.versionID,
> address,
> defaultConf);
> }
> });
>
> What puzzled me is that the job id is actually passed in as the user name to task tracker. On the Name node side, when it tries to map the non-existing user name, i.e., task id, to a group, it always returns empty array. As a result, we always see annoying warning messages such as
>
> WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
>
> Sometimes, the warning messages were thrown so fast, hundreds or even thousands per second for a big cluster, the system performance was degraded dramatically.
>
> Could someone please explain why this logic was designed in this way? Any benefit to use non-existing user for the group mapping? Or is this a bug?
>
> Thanks in advance,
>
> John
--
CONFIDENTIALITY NOTICE
NOTICE: This message is intended for the use of the individual or entity to
which it is addressed and may contain information that is confidential,
privileged and exempt from disclosure under applicable law. If the reader
of this message is not the intended recipient, you are hereby notified that
any printing, copying, dissemination, distribution, disclosure or
forwarding of this communication is strictly prohibited. If you have
received this communication in error, please contact the sender immediately
and delete it from your system. Thank You.
Re: A question about Hadoop 1 job user id used for group mapping, which could lead to performance degradatioin
Posted by Vinod Kumar Vavilapalli <vi...@hortonworks.com>.
It just seems like lazy code. You can see that, later, there is this:
{code}
for(Token<?> token : UserGroupInformation.getCurrentUser().getTokens()) {
childUGI.addToken(token);
}
{code}
So eventually the JobToken is getting added to the UGI which runs task-code.
> WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
This seems to be a problem. When the task tries to reach the NameNode, it should do so as the user, not the job-id. It is not just logging, I'd be surprised if jobs pass. Do you have permissions enabled on HDFS?
Oh, or is this in non-secure mode (i.e. without kerberos)?
+Vinod
On Jan 7, 2014, at 5:14 PM, Jian Fang <ji...@gmail.com> wrote:
> Hi,
>
> I looked at Hadoop 1.X source code and found some logic that I could not understand.
>
> In the org.apache.hadoop.mapred.Child class, there were two UGIs defined as follows.
>
> UserGroupInformation current = UserGroupInformation.getCurrentUser();
> current.addToken(jt);
>
> UserGroupInformation taskOwner
> = UserGroupInformation.createRemoteUser(firstTaskid.getJobID().toString());
> taskOwner.addToken(jt);
>
> But it is the taskOwner that is actually passed as a UGI to task tracker and then to HDFS. The first one was not referenced any where.
>
> final TaskUmbilicalProtocol umbilical =
> taskOwner.doAs(new PrivilegedExceptionAction<TaskUmbilicalProtocol>() {
> @Override
> public TaskUmbilicalProtocol run() throws Exception {
> return (TaskUmbilicalProtocol)RPC.getProxy(TaskUmbilicalProtocol.class,
> TaskUmbilicalProtocol.versionID,
> address,
> defaultConf);
> }
> });
>
> What puzzled me is that the job id is actually passed in as the user name to task tracker. On the Name node side, when it tries to map the non-existing user name, i.e., task id, to a group, it always returns empty array. As a result, we always see annoying warning messages such as
>
> WARN org.apache.hadoop.security.UserGroupInformation (IPC Server handler 63 on 9000): No groups available for user job_201401071758_0002
>
> Sometimes, the warning messages were thrown so fast, hundreds or even thousands per second for a big cluster, the system performance was degraded dramatically.
>
> Could someone please explain why this logic was designed in this way? Any benefit to use non-existing user for the group mapping? Or is this a bug?
>
> Thanks in advance,
>
> John
--
CONFIDENTIALITY NOTICE
NOTICE: This message is intended for the use of the individual or entity to
which it is addressed and may contain information that is confidential,
privileged and exempt from disclosure under applicable law. If the reader
of this message is not the intended recipient, you are hereby notified that
any printing, copying, dissemination, distribution, disclosure or
forwarding of this communication is strictly prohibited. If you have
received this communication in error, please contact the sender immediately
and delete it from your system. Thank You.