File Client Debug logging
To access MapR's filesystem MapR provides a client implementation known as FileClient. This client is necessary for all access to MapR-FS and is used by the Hadoop command line, ecosystems and hadoop (Yarn) among many other applications..
You may find that access to MapR-FS is not behaving as expected and require further details about the client behavior to debug the issue further. Example Hadoop commands hang, I/O error , Stale file handle etc
The method for enabling the debug logging within MapR's FileClient differs depending on the client or application you are using to access MapR-FS. This Blog will cover a different methods for getting debug level logging from FileClient when accessing MapR-FS.
1. Using the hadoop command line
If the access issue is observed using the hadoop command line the debug logging can be enabled directly with the command execution. For example, the original command is:
# hadoop fs -ls /
To enable debug logging add '-Dfs.mapr.trace=debug' to the command syntax and re-run the command. Ex:
hadoop fs -Dfs.mapr.trace=debug -ls /
2016-11-25 16:50:15,1428 DEBUG JniCommon fs/client/fileclient/cc/jni_MapRClient.cc:537 Thread: 4544 -- Enter JNI OpenClient --
2016-11-25 16:50:15,1482 DEBUG Client fs/client/fileclient/cc/client.cc:6571 Thread: 4544 shmemsize: 2560 raSize: 0
2016-11-25 16:50:15,1550 DEBUG Client fs/client/fileclient/cc/client.cc:6588 Thread: 4544 connect timeout value : 0
2016-11-25 16:50:15,1550 DEBUG Client fs/client/fileclient/cc/client.cc:6602 Thread: 4544 User buffersize = 1024
2016-11-25 16:50:15,1550 DEBUG Client fs/client/fileclient/cc/client.cc:6610 Thread: 4544 Group buffersize = 1024
2016-11-25 16:50:15,1553 DEBUG Client fs/client/fileclient/cc/client.cc:6659 Thread: 4544 PutBuffer memory threshold = 33554432 MB, flush interval = 3 secs, bufferSize = 131072 bytes
2016-11-25 16:50:15,1554 DEBUG Client fs/client/fileclient/cc/client.cc:6670 Thread: 4544 BulkLoader queueSz= 0MB flags=0
2016-11-25 16:50:15,1555 DEBUG Client fs/client/fileclient/cc/client.cc:1040 Thread: 4544 InitCreds: number of groups = 1
2016-11-25 16:50:15,1555 DEBUG Client fs/client/fileclient/cc/client.cc:1078 Thread: 4544 InitCreds: default user ID = 0
2016-11-25 16:50:15,1555 DEBUG Client fs/client/fileclient/cc/client.cc:1084 Thread: 4544 Added gid 0
2016-11-25 16:50:15,1708 DEBUG Client fs/client/fileclient/cc/client.cc:4487 Thread: 4544 Readdirplus: name = hbase
2016-11-25 16:50:15,1708 DEBUG Client fs/client/fileclient/cc/client.cc:4458 Thread: 4544 Readdirplus: Entry name "var" node 2049.35.131184 cookie 0xffffffffffffffff
2016-11-25 16:50:15,1708 DEBUG Client fs/client/fileclient/cc/client.cc:3464 Thread: 4544 mode = 493
2016-11-25 16:50:15,1708 DEBUG Client fs/client/fileclient/cc/client.cc:3469 Thread: 4544 uid = 2000
2016-11-25 16:50:15,1708 DEBUG Client fs/client/fileclient/cc/client.cc:3473 Thread: 4544 gid = 2000
2016-11-25 16:50:15,1711 DEBUG ApiCommon fs/client/fileclient/cc/api_common.cc:175 Thread: 4544 IdLookup: Found user: mapr, id: 2000
2016-11-25 16:50:15,1711 DEBUG ApiCommon fs/client/fileclient/cc/api_common.cc:175 Thread:Found 7 items
drwxr-xr-x - mapr mapr 1 2016-11-14 14:34 /ameya
drwxr-xr-x - mapr mapr 1 2016-11-10 10:51 /apps
drwxr-xr-x - mapr mapr 0 2016-11-01 20:33 /hbase
drwxr-xr-x - mapr mapr 0 2016-11-01 20:35 /opt
drwxrwxrwx - mapr mapr 4 2016-11-25 13:40 /tmp
drwxr-xr-x - mapr mapr 2 2016-11-14 14:33 /user
drwxr-xr-x - mapr mapr 1 2016-11-01 20:34 /var
4544 IdLookup: Found group: mapr, id: 2000
2016-11-25 16:50:15,1712 DEBUG JniCommon fs/client/fileclient/cc/jni_MapRClient.cc:439 Thread: 4544 Created JNIFileStatus obj
|
Given the operation being performed the output with this option added is likely to be very verbose. The output can be redirected to a file to review later using the following command, This will output the full debug log to a file 'debug.out' in /tmp.
# hadoop fs -Dfs.mapr.trace=debug -ls / >> /tmp/debug.out 2>&1
Same way while running job from command line file client debug logging can be turned on as below
yarn jar /opt/mapr/hadoop/hadoop-2.7.0/share/hadoop/mapreduce/hadoop-mapreduce-examples-2.7.0-mapr-1607.jar pi -Dfs.mapr.trace=DEBUG 1 2
Number of Maps = 1
Samples per Map = 2
2016-11-25 17:03:12,9225 DEBUG JniCommon fs/client/fileclient/cc/jni_MapRClient.cc:537 Thread: 16349 -- Enter JNI OpenClient --
2016-11-25 17:03:12,9234 DEBUG Client fs/client/fileclient/cc/client.cc:6571 Thread: 16349 shmemsize: 2560 raSize: 0
2016-11-25 17:03:12,9304 DEBUG Client fs/client/fileclient/cc/client.cc:6588 Thread: 16349 connect timeout value : 0
2016-11-25 17:03:12,9304 DEBUG Client fs/client/fileclient/cc/client.cc:6602 Thread: 16349 User buffersize = 1024
2016-11-25 17:03:12,9304 DEBUG Client fs/client/fileclient/cc/client.cc:6610 Thread: 16349 Group buffersize = 1024
2016-11-25 17:03:12,9309 DEBUG Client fs/client/fileclient/cc/client.cc:6659 Thread: 16349 PutBuffer memory threshold = 33554432 MB, flush interval = 3 secs, bufferSize = 131072 bytes
2016-11-25 17:03:12,9309 DEBUG Client fs/client/fileclient/cc/client.cc:6670 Thread: 16349 BulkLoader queueSz= 0MB flags=0
2016-11-25 17:03:12,9310 DEBUG Client fs/client/fileclient/cc/client.cc:1040 Thread: 16349 InitCreds: number of groups = 2
2016-11-25 17:03:12,9310 DEBUG Client fs/client/fileclient/cc/client.cc:1078 Thread: 16349 InitCreds: default user ID = 2000
2016-11-25 17:03:12,9311 DEBUG Client fs/client/fileclient/cc/client.cc:1084 Thread: 16349 Added gid 2000
2016-11-25 17:03:13,6828 DEBUG Client fs/client/fileclient/cc/client.cc:2162 Thread: 16349 SetThreadLocalDefaultUserInfo: setting default user ID of 2000
2016-11-25 17:03:13,6828 DEBUG Client fs/client/fileclient/cc/client.cc:2153 Thread: 16349 SetThreadLocalUserInfo: set user ID to 2000 in thread memory at 0x7fda70bbb5e0
2016-11-25 17:03:13,6828 DEBUG JniCommon fs/client/fileclient/cc/jni_MapRClient.cc:649 Thread: 16349 parent = /var/mapr/cluster/yarn/rm/staging/mapr/.staging/job_14789077359, end = /job.jar
2016-11-25 17:03:13,6828 DEBUG Client fs/client/fileclient/cc/client.cc:2819 Thread: 16349 >TraverseAndCreateDirs: parentName /var/mapr/cluster/yarn/rm/staging/mapr/.staging/job_14789077359, child (nil)
2016-11-25 17:03:13,6828 DEBUG Client fs/client/fileclient/cc/client.cc:2834 Thread: 16349 TraverseAndCreateDirs: Path /var/mapr/cluster/yarn/rm/staging/mapr/.staging/job_14789077359 fid:2114.40.393848 found in fidcache
2016-11-25 17:03:14,1723 DEBUG ApiCommon fs/client/fileclient/cc/api_common.cc:175 Thread: 16349 IdLookup: Found user: mapr, id: 2000
2016-11-25 17:03:14,1723 DEBUG ApiCommon fs/client/fileclient/cc/api_common.cc:175 Thread: 16349 IdLookup: Found group: mapr, id: 2000
2016-11-25 17:03:14,1723 DEBUG JniCommon fs/client/fileclient/cc/jni_MapRClient.cc:439 Thread: 16349 Created JNIFileStatus obj
16/11/25 17:03:14 INFO impl.YarnClientImpl: Submitted application application_1478907735945_0006
16/11/25 17:03:14 INFO mapreduce.Job: The url to track the job: http://node10.maprlab.local:8088/proxy/application_1478907735945_0006/
16/11/25 17:03:14 INFO mapreduce.Job: Running job: job_1478907735945_0006
16/11/25 17:03:22 INFO mapreduce.Job: Job job_1478907735945_0006 running in uber mode : false
16/11/25 17:03:22 INFO mapreduce.Job: map 0% reduce 0%
16/11/25 17:03:28 INFO mapreduce.Job: map 100% reduce 0%
16/11/25 17:03:33 INFO mapreduce.Job: map 100% reduce 100%
16/11/25 17:03:33 INFO mapreduce.Job: Job job_1478907735945_0006 completed successfully
16/11/25 17:03:33 INFO mapreduce.Job: Counters: 46
File System Counters
FILE: Number of bytes read=0
FILE: Number of bytes written=193533
FILE: Number of read operations=0
FILE: Number of large read operations=0
FILE: Number of write operations=0
MAPRFS: Number of bytes read=336
MAPRFS: Number of bytes written=303
MAPRFS: Number of read operations=43
MAPRFS: Number of large read operations=0
MAPRFS: Number of write operations=59
Job Counters
Launched map tasks=1
Launched reduce tasks=1
Data-local map tasks=1
Total time spent by all maps in occupied slots (ms)=3281
Total time spent by all reduces in occupied slots (ms)=9231
Total time spent by all map tasks (ms)=3281
Total time spent by all reduce tasks (ms)=3077
Total vcore-seconds taken by all map tasks=3281
Total vcore-seconds taken by all reduce tasks=3077
Total megabyte-seconds taken by all map tasks=3359744
Total megabyte-seconds taken by all reduce tasks=9452544
DISK_MILLIS_MAPS=1641
DISK_MILLIS_REDUCES=4092
Map-Reduce Framework
Map input records=1
Map output records=2
Map output bytes=18
Map output materialized bytes=0
Input split bytes=134
Combine input records=0
Combine output records=0
Reduce input groups=2
Reduce shuffle bytes=24
Reduce input records=2
Reduce output records=0
Spilled Records=4
Shuffled Maps =1
Failed Shuffles=0
Merged Map outputs=2
GC time elapsed (ms)=153
CPU time spent (ms)=1200
Physical memory (bytes) snapshot=890372096
Virtual memory (bytes) snapshot=5562601472
Total committed heap usage (bytes)=874512384
Shuffle Errors
IO_ERROR=0
File Input Format Counters
Bytes Read=118
File Output Format Counters
Bytes Written=97
Job Finished in 20.913 seconds
9 -- Exit createJNIFileStatus --
2016-11-25 17:03:33,9136 DEBUG JniCommon fs/client/fileclient/cc/jni_MapRClient.cc:1015 Thread: 16349 -- Enter JNI getattr -- /user/mapr/QuasiMonteCarlo_1480122192058_2027324396/out/reduce-
2016-11-25 17:03:33,9136 DEBUG ApiCommon fs/client/fileclient/cc/api_common.cc:1802 Thread: 16349 ApiCommonSetThreadUser: Obtaining the object info for UserInfo object 0x7fda7934b000
2016-11-25 17:03:33,9136 DEBUG Client fs/client/fileclient/cc/client.cc:2162 Thread: 16349 SetThreadLocalDefaultUserInfo: setting default user ID of 2000
2016-11-25 17:03:33,9136 DEBUG Client fs/client/fileclient/cc/client.cc:2153 Thread: 16349 SetThreadLocalUserInfo: set user ID to 2000 in thread memory at 0x7fda70bbb5e0
2016-11-25 17:03:33,9380 DEBUG Inode fs/client/fileclient/cc/inode.cc:641 Thread: 16349 itab:inval >2059.32.131264 back to lr
Estimated value of Pi is 4.00000000000000000000
u 0x7fda70eaf4b0
2016-11-25 17:03:33,9381 DEBUG JniCommon fs/client/fileclient/cc/jni_MapRClient.cc:973 Thread: 16349 -- Exit JNI remove -- /user/mapr/QuasiMonteCarlo_1480122192058_2027324396
|
2. Using core-site.xml
If the issue being observed when accessing MapR-FS from map-reduce tasks or any application where '-Dfs.mapr.trace=debug' option cannot be invoked directly the debug logging can be enabled in core-site.xml. This method can also be used for debugging the command line so the '-Dfs.mapr.trace=debug' option is not needed on every invocation. Depending on your Hadoop version core-site.xml will be under /opt/mapr/hadoop/hadoop-0.20.2/conf/ or /opt/mapr/hadoop/hadoop-*/etc/hadoop/core-site.xml. Add the following property to core-site.xml and save the changes:
<property> <name>fs.mapr.trace</name> <value>debug</value> </property> |
Note that making this change in core-site.xml will affect every process that accesses MapR-FS using FileClient and will result in verbose debug output printed to the process stderr.
3. Programmatically within application code
If the issue being observed when accessing MapR-FS is from user application code the 'fs.mapr.trace' configuration can be added directly to the application configuration code. Ex:
Configuration conf = new Configuration(); conf.set("fs.mapr.trace","debug");
|
This will enable FileClient debug logging when the application code is run and calls are made to access MapR-FS.
No comments:
Post a Comment