Skip to main content

HDFS debugging scenario

Listen:

The first step to debug issues in a running hadoop - environment to take a look at the stacktraces, easy accessible over jobtracker/stacks and let you show all running stacks in a jstack view. You will see the running processes, as an example I discuss a lab testing scenario, see below.

http://jobtracker:50030/stacks

Process Thread Dump: 
43 active threads
Thread 3203101 (IPC Client (47) connection to NAMENODE/IP:9000 from hdfs):
  State: TIMED_WAITING
  Blocked count: 6
  Waited count: 7
  Stack:
    java.lang.Object.wait(Native Method)
    org.apache.hadoop.ipc.Client$Connection.waitForWork(Client.java:676)
    org.apache.hadoop.ipc.Client$Connection.run(Client.java:719)

In that case the RPC connection has a state "TIMED_WAIT" in a block and waited count. That means, the namenode could not answer the RPC request fast enough. The problem belongs the setup as I see often in production environments.
For demonstration I use a ESX Cluster with a VM for the namenode. The ESX abstraction layer for networks isn't performant enough and block the requests. It is always a good idea to use physical servers for infrastructure and services.
Another problem I figured out depends on HP Bladecenter switches from Nortel, a newer update set a hidden switch "dos-filter", disable it. The switch will block all traffic which looks like a DOS attack. That's a serious bug and I wondering why such params are delivered and enabled per default.

Now we take a closer look at the namenode:

With "jps" you can list all running java-processes:
jps
24158 SecondaryNameNode
31684 FlumeMaster
7898 JobTracker
18613 NameNode
16631 Jps
31653 FlumeWatchdog

We check the logs with "tail -f /var/log/hadoop-0.20/*.log|grep -i error". If you sure that all things are well you should look at the java-threads on the jobtracker. With "top -Hc" you'll see the threads and the running command:

Mem:   4043792k total,  3916788k used,   127004k free,   352684k buffers
Swap:  5242864k total,  1448628k used,  3794236k free,   653296k cached


  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
18448 hdfs      17   0 2345m 102m  12m S 55.1  1.3   0:01.66 /usr/java/jdk1.6.0_23/bin/java -Dproc_jar -Xmx2000m -Dhadoo
18458 hdfs      16   0 2345m 102m  12m S 31.5  1.3   0:00.95 /usr/java/jdk1.6.0_23/bin/java -Dproc_jar -Xmx2000m -Dhadoo
18457 hdfs      15   0 2345m 102m  12m R 30.9  1.3   0:00.93 /usr/java/jdk1.6.0_23/bin/java -Dproc_jar -Xmx2000m -Dhadoo
18356 hdfs      15   0 2510m 544m  11m S  1.3  6.8   0:00.06 jsvc.exec -Dproc_datanode -pidfile /usr/lib/hadoop-0.20/pid
18366 hdfs      18   0 2345m 102m  12m S  0.7  1.3   0:00.02 /usr/java/jdk1.6.0_23/bin/java -Dproc_jar -Xmx2000m -Dhadoo

to check the IO load on a running job you can use vmstat (sysstat-package):

vmstat -n 2 
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0 1707244 368124 296528 482624    0    0     0   276 1626 1336 14 17 68  1  0
 0  0 1707244 367752 296544 482724    0    0     0   144 1362  716  2  1 97  0  0
 0  0 1707244 366884 296564 482728    0    0     8    66 1268  750  2  3 94  1  0
 1  0 1707244 366216 296588 482736    0    0     8   260 1269  672  2  4 94  1  0

Here we see a snippet with a running hive-job, the system has no problems with IO, but the interrupts and context switching looks a bit high. That depends on setup, it is always a bad idea to run all services on a single server instance.

Ex. Solution:
The namenode is going deeply into swap, so the first case should be to add more RAM (it was a testcluster with 5 nodes and a VM as namenode to reproduce some timing errors).
Remember, each block of HDFS take 4kb RAM usage on the namenode. The best case here will be to split the services in single instances (jobtracker, namenode and secondary namenode should be outsourced).

Another effective way would be to write a debugscript [1] and use setStatus() and incrCounter() methods on Reporter. Let run your debug script in streaming mode and use the cmd-line-options "-mapdebug" and "-reducedebug".

[1] http://hadoop.apache.org/common/docs/current/mapred_tutorial.html#Debugging

Comments

Popular posts from this blog

Deal with corrupted messages in Apache Kafka

Under some strange circumstances, it can happen that a message in a Kafka topic is corrupted. This often happens when using 3rd party frameworks with Kafka. In addition, Kafka < 0.9 does not have a lock on Log.read() at the consumer read level, but does have a lock on Log.write(). This can lead to a rare race condition as described in KAKFA-2477 [1]. A likely log entry looks like this: ERROR Error processing message, stopping consumer: (kafka.tools.ConsoleConsumer$) kafka.message.InvalidMessageException: Message is corrupt (stored crc = xxxxxxxxxx, computed crc = yyyyyyyyyy Kafka-Tools Kafka stores the offset of each consumer in Zookeeper. To read the offsets, Kafka provides handy tools [2]. But you can also use zkCli.sh, at least to display the consumer and the stored offsets. First we need to find the consumer for a topic (> Kafka 0.9): bin/kafka-consumer-groups.sh --zookeeper management01:2181 --describe --group test Prior to Kafka 0.9, the only way to get this inform

Hive query shows ERROR "too many counters"

A hive job face the odd " Too many counters:"  like Ended Job = job_xxxxxx with exception 'org.apache.hadoop.mapreduce.counters.LimitExceededException(Too many counters: 201 max=200)' FAILED: Execution Error, return code 1 from org.apache.hadoop.hive.ql.exec.MapRedTask Intercepting System.exit(1) These happens when operators are used in queries ( Hive Operators ). Hive creates 4 counters per operator, max upto 1000, plus a few additional counters like file read/write, partitions and tables. Hence the number of counter required is going to be dependent upon the query.  To avoid such exception, configure " mapreduce.job.counters.max " in mapreduce-site.xml to a value above 1000. Hive will fail when he is hitting the 1k counts, but other MR jobs not. A number around 1120 should be a good choice. Using " EXPLAIN EXTENDED " and " grep -ri operators | wc -l " print out the used numbers of operators. Use this value to tweak the MR s

AI's False Reality: Understanding Hallucination

Artificial Intelligence (AI) has leapfrogged to the poster child of technological innovation, on track to transform industries in a scale similar to the Industrial Revolution of the 1800s. But in this case, as cutting-edge technology, AI presents its own unique challenge, exploiting our human behavior of "love to trust", we as humans face a challenge: AI hallucinations. This phenomenon, where AI models generate outputs that are factually incorrect, misleading, or entirely fabricated, raises complex questions about the reliability and trust of AI models and larger systems. The tendency for AI to hallucinate comes from several interrelated factors. Overfitting – a condition where models become overly specialized to their training data – can lead to confident but wildly inaccurate responses when presented with novel scenarios (Guo et al., 2017). Moreover, biases embedded within datasets shape the models' understanding of the world; if these datasets are flawed or unreprese