Re: NameNode deadlocked (help?)
Brian Bockelman wrote: On May 14, 2010, at 8:27 PM, Todd Lipcon wrote: Hey Brian, Yep, excessive GC definitely sounds like a likely culprit. I'm surprised you didn't see OOMEs in the log, though. We didn't until the third restart today. I have no clue why we haven't seen this in the past 9 months of this cluster though... Anyhow, it looks like this might have done the trick... the sysadmin is heading over to kick over a few errant datanodes, and we should be able to get out of safemode soon. Luckily, it's a 4-day weekend in Europe and otherwise a Friday evening in the US, so there's only a few folks using it. good thing we europeans have long weekends. If you want to monitor GC, I'd recommend adding -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps to your java options - occasionally useful for times like this. What are your current GC options? Played with compressed object pointers yet?
Re: NameNode deadlocked (help?)
On May 17, 2010, at 5:25 AM, Steve Loughran wrote: Brian Bockelman wrote: On May 14, 2010, at 8:27 PM, Todd Lipcon wrote: Hey Brian, Yep, excessive GC definitely sounds like a likely culprit. I'm surprised you didn't see OOMEs in the log, though. We didn't until the third restart today. I have no clue why we haven't seen this in the past 9 months of this cluster though... Anyhow, it looks like this might have done the trick... the sysadmin is heading over to kick over a few errant datanodes, and we should be able to get out of safemode soon. Luckily, it's a 4-day weekend in Europe and otherwise a Friday evening in the US, so there's only a few folks using it. good thing we europeans have long weekends. :) Indeed If you want to monitor GC, I'd recommend adding -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps to your java options - occasionally useful for times like this. What are your current GC options? Played with compressed object pointers yet? I've been eyeballing them, but haven't had any chance yet. We probably won't mess with them until we start to run out of RAM on the machine themselves. This particular instance was a simple oversight - there was no need to try and fit the NN into a 1GB heap on a dedicated machine. I tell folks 1GB RAM per 1M objects. It's almost always an over-estimate but, better safe than deadlocked on a Friday evening... Brian smime.p7s Description: S/MIME cryptographic signature
Re: NameNode deadlocked (help?)
Brian Bockelman wrote: On May 17, 2010, at 5:25 AM, Steve Loughran wrote: Brian Bockelman wrote: On May 14, 2010, at 8:27 PM, Todd Lipcon wrote: Hey Brian, Yep, excessive GC definitely sounds like a likely culprit. I'm surprised you didn't see OOMEs in the log, though. We didn't until the third restart today. I have no clue why we haven't seen this in the past 9 months of this cluster though... Anyhow, it looks like this might have done the trick... the sysadmin is heading over to kick over a few errant datanodes, and we should be able to get out of safemode soon. Luckily, it's a 4-day weekend in Europe and otherwise a Friday evening in the US, so there's only a few folks using it. good thing we europeans have long weekends. :) Indeed If you want to monitor GC, I'd recommend adding -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps to your java options - occasionally useful for times like this. What are your current GC options? Played with compressed object pointers yet? I've been eyeballing them, but haven't had any chance yet. We probably won't mess with them until we start to run out of RAM on the machine themselves. This particular instance was a simple oversight - there was no need to try and fit the NN into a 1GB heap on a dedicated machine. I tell folks 1GB RAM per 1M objects. It's almost always an over-estimate but, better safe than deadlocked on a Friday evening... I've been using compressed pointers on JRockit for a long time, a very nice JVM that doesn't ever seem to run out of stack when you accidentally tail recurse without end. The Sun JVM pointers are newer, not had any problems with that part of the JVM, and the benefits in both memory consumption and possibly in cache hits make it very appealing.
NameNode deadlocked (help?)
Hey guys, I know it's 5PM on a Friday, but we just saw one of our big cluster's namenode's deadlock. This is 0.19.1; does this ring a bell for anyone? I haven't had any time to start going through source code, but I figured I'd send out a SOS in case if this looked familiar. We had restarted this cluster a few hours ago and made the following changes: 1) Increased the number of datanode handlers from 10 to 40. 2) Increased ipc.server.listen.queue.size from 128 to 256. If nothing else, I figure a deadlocked NN might be interesting to devs... Brian 2010-05-14 17:11:30 Full thread dump Java HotSpot(TM) 64-Bit Server VM (11.2-b01 mixed mode): IPC Server handler 39 on 9000 daemon prio=10 tid=0x2aaafc181400 nid=0x4cd waiting for monitor entry [0x45962000..0x45962d90] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.handleHeartbeat(FSNamesystem.java:2231) - waiting to lock 0x2aaab3653848 (a java.util.ArrayList) at org.apache.hadoop.hdfs.server.namenode.NameNode.sendHeartbeat(NameNode.java:625) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 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:481) at org.apache.hadoop.ipc.Server$Handler.run(Server.java:894) IPC Server handler 38 on 9000 daemon prio=10 tid=0x2aaafc17f800 nid=0x4cc waiting for monitor entry [0x45861000..0x45861d10] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getStats(FSNamesystem.java:3326) - waiting to lock 0x2aaab3653848 (a java.util.ArrayList) at org.apache.hadoop.hdfs.server.namenode.NameNode.getStats(NameNode.java:505) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 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:481) at org.apache.hadoop.ipc.Server$Handler.run(Server.java:894) IPC Server handler 37 on 9000 daemon prio=10 tid=0x2aaafc17e000 nid=0x4cb waiting for monitor entry [0x4575f000..0x45760a90] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getBlockLocationsInternal(FSNamesystem.java:801) - waiting to lock 0x2aaab3843e40 (a org.apache.hadoop.hdfs.server.namenode.FSNamesystem) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getBlockLocations(FSNamesystem.java:784) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getBlockLocations(FSNamesystem.java:751) at org.apache.hadoop.hdfs.server.namenode.NameNode.getBlockLocations(NameNode.java:272) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 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:481) at org.apache.hadoop.ipc.Server$Handler.run(Server.java:894) IPC Server handler 36 on 9000 daemon prio=10 tid=0x2aaafc17c400 nid=0x4ca waiting for monitor entry [0x4565e000..0x4565fa10] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.blockReceived(FSNamesystem.java:3281) - waiting to lock 0x2aaab3843e40 (a org.apache.hadoop.hdfs.server.namenode.FSNamesystem) at org.apache.hadoop.hdfs.server.namenode.NameNode.blockReceived(NameNode.java:649) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 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:481) at org.apache.hadoop.ipc.Server$Handler.run(Server.java:894) IPC Server handler 35 on 9000 daemon prio=10 tid=0x2aaafc17a800 nid=0x4c9 waiting for monitor entry [0x4555e000..0x4555eb90] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getAdditionalBlock(FSNamesystem.java:1294) - waiting to lock 0x2aaab3843e40 (a
Re: NameNode deadlocked (help?)
Hey Brian, Looks like it's not deadlocked, but rather just busy doing a lot of work: org.apache.hadoop.hdfs.server.namenode.fsnamesystem$heartbeatmoni...@1c778255 daemon prio=10 tid=0x2aaafc012c00 nid=0x493 runnable [0x413da000..0x413daa10] java.lang.Thread.State: RUNNABLE at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.removeStoredBlock(FSNamesystem.java:3236) - locked 0x2aaab3843e40 (a org.apache.hadoop.hdfs.server.namenode.FSNamesystem) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.removeDatanode(FSNamesystem.java:2695) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.heartbeatCheck(FSNamesystem.java:2785) - locked 0x2aaab3659dd8 (a java.util.TreeMap) - locked 0x2aaab3653848 (a java.util.ArrayList) - locked 0x2aaab3843e40 (a org.apache.hadoop.hdfs.server.namenode.FSNamesystem) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem$HeartbeatMonitor.run(FSNamesystem.java:2312) at java.lang.Thread.run(Thread.java:619) Let me dig up the 19.1 source code and see if this looks like an infinite loop or just one that's tying it up for some number of seconds. Anything being written into the logs? -Todd On Fri, May 14, 2010 at 5:22 PM, Brian Bockelman bbock...@cse.unl.eduwrote: Hey guys, I know it's 5PM on a Friday, but we just saw one of our big cluster's namenode's deadlock. This is 0.19.1; does this ring a bell for anyone? I haven't had any time to start going through source code, but I figured I'd send out a SOS in case if this looked familiar. We had restarted this cluster a few hours ago and made the following changes: 1) Increased the number of datanode handlers from 10 to 40. 2) Increased ipc.server.listen.queue.size from 128 to 256. If nothing else, I figure a deadlocked NN might be interesting to devs... Brian 2010-05-14 17:11:30 Full thread dump Java HotSpot(TM) 64-Bit Server VM (11.2-b01 mixed mode): IPC Server handler 39 on 9000 daemon prio=10 tid=0x2aaafc181400 nid=0x4cd waiting for monitor entry [0x45962000..0x45962d90] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.handleHeartbeat(FSNamesystem.java:2231) - waiting to lock 0x2aaab3653848 (a java.util.ArrayList) at org.apache.hadoop.hdfs.server.namenode.NameNode.sendHeartbeat(NameNode.java:625) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 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:481) at org.apache.hadoop.ipc.Server$Handler.run(Server.java:894) IPC Server handler 38 on 9000 daemon prio=10 tid=0x2aaafc17f800 nid=0x4cc waiting for monitor entry [0x45861000..0x45861d10] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getStats(FSNamesystem.java:3326) - waiting to lock 0x2aaab3653848 (a java.util.ArrayList) at org.apache.hadoop.hdfs.server.namenode.NameNode.getStats(NameNode.java:505) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 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:481) at org.apache.hadoop.ipc.Server$Handler.run(Server.java:894) IPC Server handler 37 on 9000 daemon prio=10 tid=0x2aaafc17e000 nid=0x4cb waiting for monitor entry [0x4575f000..0x45760a90] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getBlockLocationsInternal(FSNamesystem.java:801) - waiting to lock 0x2aaab3843e40 (a org.apache.hadoop.hdfs.server.namenode.FSNamesystem) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getBlockLocations(FSNamesystem.java:784) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getBlockLocations(FSNamesystem.java:751) at org.apache.hadoop.hdfs.server.namenode.NameNode.getBlockLocations(NameNode.java:272) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) 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:481) at org.apache.hadoop.ipc.Server$Handler.run(Server.java:894)
