The below looks same as blockage seen in logs posted to hbase-2545 by Kris Jirapinyo.
Todd has made a fix and added a test. We'll roll a 0.20.5 hbase with this fix and a fix for hbase-2541 (missing licenses from the head of some source files) soon as we get confirmation that Todd's fix works for Kris Jirapinyo's seemingly similar issue. Thanks, St.Ack On Fri, May 14, 2010 at 9:07 AM, Todd Lipcon <t...@cloudera.com> wrote: > It appears like we might be stuck in an infinite loop here: > > "IPC Server handler 9 on 60020" daemon prio=10 tid=0x00002aaeb42f7800 > nid=0x6508 runnable [0x00000000445bb000] > java.lang.Thread.State: RUNNABLE > at > org.apache.hadoop.hbase.regionserver.ExplicitColumnTracker.checkColumn(ExplicitColumnTracker.java:128) > at > org.apache.hadoop.hbase.regionserver.ScanQueryMatcher.match(ScanQueryMatcher.java:165) > at > org.apache.hadoop.hbase.regionserver.StoreScanner.next(StoreScanner.java:176) > > It's holding a lock that some other threads are blocked on. In both of your > pastes, there are some threads stuck here. > > JD, any thoughts? Looks like you made some changes to this code for 0.20.4. > > -Todd > > On Fri, May 14, 2010 at 6:56 AM, Friso van Vollenhoven < > fvanvollenho...@xebia.com> wrote: > >> Hi Todd, >> >> The row counting works fine. It is quite slow, I have to say. But I have >> never used row counting from the shell before, so I don't know what >> performance to expect from it or how it is implemented. It's just that a >> regular scan from software is way faster. >> >> Also, from our application we do a full table scan to populate an in-memory >> index of row keys, because we need to be able to quickly determine if a >> certain key exists or not. I triggered this scan from our UI while there >> were hanging reducers. This also works fine. There are close to 5 million >> records in the table and I checked in the web interface that the table is >> divided across all 4 region servers, so this process should hit them all. >> >> The earlier jstacks of the region servers were taken when the reducers >> (clients) were hanging, before the shutdown was requested. Some 3 to 5 >> reduce tasks hang, not all of them, but surely more than just one. >> >> Because of your question about what is locked up (client or region server), >> I SSH'ed into each of the worker machines after giving HBase the shutdown >> signal (so the shutdown sequence started) and tried to see if the region >> server was still running and if so, shutdown each individual region server >> manually (doing 'hbase-daemon.sh stop regionserver' on each, I'm glad there >> are only 4 nodes). I found that: >> - one of the region servers actually shut down normally (worker3) >> - two region servers shut down normally after the hbase-daemon.sh command >> (worker4 and worker1) >> - one region server does not shut down (worker2) >> >> I put some additional info on pastebin. >> >> Here is the jstack of worker2 (the hanging one): >> http://pastebin.com/5V0UZi7N >> There are two jstack outputs, one from before the shutdown command was >> given and one (starting at line 946) from after the shutdown command was >> given. >> >> Here are the logs of that region server: http://pastebin.com/qCXSKR2A >> I set the log level for org.apache.hadoop.hbase to DEBUG before doing all >> this, so it's more verbose (I don't know if this helps). >> >> So, it appears that it is one of the region servers that is locked up, but >> only for some connections while it can still serve other connections >> normally. From the locked up region server logs, it looks like the shutdown >> sequence runs completely, but the server just won't die afterwards (because >> of running non-daemon threads; maybe it should just do a System.exit() if >> all cleanup is successful). At least nothing gets corrupted, which is nice. >> Of course I am still trying to find out why things get locked up in the >> first place. >> >> I did this test twice today. During the first run it was a different region >> server that was hanging, so I think it has nothing to do with a problem >> related to that specific machine. >> >> My next step is to go through code (including HBase's, so It will take me >> some time...) and see what exactly happens in our scenario, because from my >> current knowledge the jstack outputs don't mean enough to me. >> >> >> >> Friso >> >> >> >> >> On May 13, 2010, at 7:09 PM, Todd Lipcon wrote: >> >> > Hi Friso, >> > >> > When did you take the jstack dumps of the region servers? Was it when the >> > reduce tasks were still hanging? >> > >> > Do all of the reduce tasks hang or is it just one that gets stuck? >> > >> > If, once the reduce tasks are hung, you open the hbase shell and run >> "count >> > 'mytable', 100000" does it successfully count the rows? >> > >> > (I'm trying to determine if the client is locked up, or one of the RSes >> is >> > locked up) >> > >> > Enjoy your holiday! >> > >> > -Todd >> > >> > On Thu, May 13, 2010 at 12:38 AM, Friso van Vollenhoven < >> > fvanvollenho...@xebia.com> wrote: >> > >> >> Hi, >> >> >> >> I was kind of hoping that this was a known thing and I was just >> overlooking >> >> something. Apparently it requires more investigation. >> >> >> >> I reproduced the situation and gathered some more info. I still have to >> >> look through everything myself a bit more (today is a national holiday >> in >> >> The Netherlands, so not much working), but I posted some info to >> pastebin. >> >> >> >> I did the following sequence (with HBase 0.20.4): >> >> - startup HBase (waited for all the regions to come online and let it >> >> settle) >> >> - startup our application >> >> - wait for the importer job to hang (it only happened on the second run, >> >> which started 15 reducers; the first run was really small and only one >> key >> >> was generated, so just one reducer) >> >> - kill the hanging importer job (hadoop job -kill) >> >> - try to shutdown HBase (as I type this it is still producing dots on my >> >> console) >> >> >> >> The HBase master logs are here (includes shutdown attempt): >> >> http://pastebin.com/PYpPVcyK >> >> The jstacks are here: >> >> - HMaster: http://pastebin.com/Da6jCAuA (this includes two thread >> dumps, >> >> one during operation with the hanging clients and one during hanging >> >> shutdown) >> >> - RegionServer 1: http://pastebin.com/5dQXfxCn >> >> - RegionServer 2: http://pastebin.com/XWwBGXYC >> >> - RegionServer 3: http://pastebin.com/mDgWbYGV >> >> - RegionServer 4: http://pastebin.com/XDR14bth >> >> >> >> As you can see in the master logs, the shutdown cannot get a thread >> called >> >> Thread-10 to stop running. The trace for that thread looks like this: >> >> "Thread-10" prio=10 tid=0x000000004d218800 nid=0x1e73 in Object.wait() >> >> [0x00000000427a7000] >> >> java.lang.Thread.State: TIMED_WAITING (on object monitor) >> >> at java.lang.Object.wait(Native Method) >> >> - waiting on <0x00002aaab364c9d0> (a java.lang.Object) >> >> at org.apache.hadoop.hbase.util.Sleeper.sleep(Sleeper.java:89) >> >> - locked <0x00002aaab364c9d0> (a java.lang.Object) >> >> at org.apache.hadoop.hbase.Chore.run(Chore.java:76) >> >> >> >> I still have no clue what happened, but I will investigate a bit more >> >> tomorrow. >> >> >> >> >> >> Thanks for the responses. >> >> >> >> >> >> Friso >> >> >> >> >> >> >> >> On May 12, 2010, at 9:02 PM, Todd Lipcon wrote: >> >> >> >>> Hi Friso, >> >>> >> >>> Also, if you can capture a jstack of the regionservers at thie time >> >>> that would be great. >> >>> >> >>> -Todd >> >>> >> >>> On Wed, May 12, 2010 at 9:26 AM, Jean-Daniel Cryans < >> jdcry...@apache.org> >> >> wrote: >> >>>> Friso, >> >>>> >> >>>> Unfortunately it's hard to determine the cause with the provided >> >>>> information, the client call you pasted is pretty much normal i.e. the >> >>>> client is waiting to receive a result from a region server. >> >>>> >> >>>> The fact that you can't shut down the master when this happens is very >> >>>> concerning. Do you still have those logs around? Same for the region >> >>>> servers? Can you post this in pastebin or on a web server? >> >>>> >> >>>> Also, feel free to come chat with us on IRC, it's always easier to >> >>>> debug when live. #hbase on freenode >> >>>> >> >>>> J-D >> >>>> >> >>>> On Wed, May 12, 2010 at 8:31 AM, Friso van Vollenhoven >> >>>> <fvanvollenho...@xebia.com> wrote: >> >>>>> Hi all, >> >>>>> >> >>>>> I am using Hadoop (0.20.2) and HBase to periodically import data >> (every >> >> 15 minutes). There are a number of import processes, but generally they >> all >> >> create a sequence file on HDFS, which is then run through a MapReduce >> job. >> >> The MapReduce uses the identity mapper (the input file is a Hadoop >> sequence >> >> file) and a specialized reducer that does the following: >> >>>>> - Combine the values for a key into one value >> >>>>> - Do a Get from HBase to retrieve existing values for the same key >> >>>>> - Combine the existing value from HBase and the new one into one >> value >> >> again >> >>>>> - Put the final value into HBase under the same key (thus 'overwrite' >> >> the existing row; I keep only one version) >> >>>>> >> >>>>> After I upgraded HBase to the 0.20.4 release, the reducers sometimes >> >> start hanging on a Get. When the jobs start, some reducers run to >> completion >> >> fine, but after a while the last reducers will start to hang. Eventually >> the >> >> reducers are killed of by Hadoop (after 600 secs). >> >>>>> >> >>>>> I did a thread dump for one of the hanging reducers. It looks like >> >> this: >> >>>>> "main" prio=10 tid=0x0000000048083800 nid=0x4c93 in Object.wait() >> >> [0x00000000420ca000] >> >>>>> java.lang.Thread.State: WAITING (on object monitor) >> >>>>> at java.lang.Object.wait(Native Method) >> >>>>> - waiting on <0x00002aaaaeb50d70> (a >> >> org.apache.hadoop.hbase.ipc.HBaseClient$Call) >> >>>>> at java.lang.Object.wait(Object.java:485) >> >>>>> at >> >> org.apache.hadoop.hbase.ipc.HBaseClient.call(HBaseClient.java:721) >> >>>>> - locked <0x00002aaaaeb50d70> (a >> >> org.apache.hadoop.hbase.ipc.HBaseClient$Call) >> >>>>> at >> >> org.apache.hadoop.hbase.ipc.HBaseRPC$Invoker.invoke(HBaseRPC.java:333) >> >>>>> at $Proxy2.get(Unknown Source) >> >>>>> at >> org.apache.hadoop.hbase.client.HTable$4.call(HTable.java:450) >> >>>>> at >> org.apache.hadoop.hbase.client.HTable$4.call(HTable.java:448) >> >>>>> at >> >> >> org.apache.hadoop.hbase.client.HConnectionManager$TableServers.getRegionServerWithRetries(HConnectionManager.java:1050) >> >>>>> at org.apache.hadoop.hbase.client.HTable.get(HTable.java:447) >> >>>>> at >> >> >> net.ripe.inrdb.hbase.accessor.real.HBaseTableAccessor.get(HBaseTableAccessor.java:36) >> >>>>> at >> >> >> net.ripe.inrdb.hbase.store.HBaseStoreUpdater.getExistingRecords(HBaseStoreUpdater.java:101) >> >>>>> at >> >> >> net.ripe.inrdb.hbase.store.HBaseStoreUpdater.mergeTimelinesWithExistingRecords(HBaseStoreUpdater.java:60) >> >>>>> at >> >> >> net.ripe.inrdb.hbase.store.HBaseStoreUpdater.doInsert(HBaseStoreUpdater.java:40) >> >>>>> at >> >> >> net.ripe.inrdb.core.store.SinglePartitionStore$Updater.insert(SinglePartitionStore.java:92) >> >>>>> at >> >> >> net.ripe.inrdb.core.store.CompositeStore$CompositeStoreUpdater.insert(CompositeStore.java:142) >> >>>>> at >> >> >> net.ripe.inrdb.importer.StoreInsertReducer.reduce(StoreInsertReducer.java:70) >> >>>>> at >> >> >> net.ripe.inrdb.importer.StoreInsertReducer.reduce(StoreInsertReducer.java:17) >> >>>>> at org.apache.hadoop.mapreduce.Reducer.run(Reducer.java:176) >> >>>>> at >> >> org.apache.hadoop.mapred.ReduceTask.runNewReducer(ReduceTask.java:566) >> >>>>> at org.apache.hadoop.mapred.ReduceTask.run(ReduceTask.java:408) >> >>>>> at org.apache.hadoop.mapred.Child.main(Child.java:170) >> >>>>> >> >>>>> So the client hangs in a wait() call, waiting on a HBaseClient$Call >> >> object. I looked at the code. The wait is in a while() loop and has no >> time >> >> out, so it figures that it never gets out of there if no notify() gets >> >> called on the object. I am not sure for exactly what condition it is >> >> waiting, however. >> >>>>> >> >>>>> Meanwhile, after this has happened, I cannot shutdown the master >> server >> >> normally. I have to kill -9 it, to make it shut down. Normally and >> before >> >> this problem occurs, the master server shuts down just fine. (Sorry, >> didn't >> >> do a thread dump of the master and now I downgraded to 0.20.3 again.) >> >>>>> >> >>>>> I cannot reproduce this error on my local setup (developer machine). >> It >> >> only occurs on our (currently modest) cluster of one machine running >> >> master+NN+Zookeeper and four datanodes which are all task trackers and >> >> region servers as well. The inputs to the periodic MapReduce jobs are >> very >> >> small (ranging from some Kb to several Mb) and thus contain not so many >> >> records. I know this is not very efficient to do in MapReduce and will >> be >> >> faster when inserted in process by the importer process because of >> startup >> >> overhead, but we are setting up this architecture of importers and >> insertion >> >> for anticipated larger loads (up to 80 million records per day). >> >>>>> >> >>>>> Does anyone have a clue about what happens? Or where to look for >> >> further investigation? >> >>>>> >> >>>>> Thanks a lot! >> >>>>> >> >>>>> >> >>>>> Cheers, >> >>>>> Friso >> >>>>> >> >>>>> >> >>>> >> >>> >> >>> >> >>> >> >>> -- >> >>> Todd Lipcon >> >>> Software Engineer, Cloudera >> >> >> >> >> > >> > >> > -- >> > Todd Lipcon >> > Software Engineer, Cloudera >> >> > > > -- > Todd Lipcon > Software Engineer, Cloudera >
