You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@htrace.apache.org by "stack (JIRA)" <ji...@apache.org> on 2015/12/10 07:55:11 UTC
[jira] [Updated] (HTRACE-330) Add to Tracer, TRACE-level logging of
push and pop of contexts to aid debugging "Can't close TraceScope.."
[ https://issues.apache.org/jira/browse/HTRACE-330?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
stack updated HTRACE-330:
-------------------------
Attachment: trace.push.pop.logging.patch
When trace is enabled on the tracer, the emissions are ugly but they helped me find an issue in the process I'm trying to instrument where we create an object but skip the close (and hence the close of the scope).
The emissions are really ugly... but it allowed me find my issue quickly (alternative is to try and use UI with a span id... and dig around but my process is not emitting wholesome spans yet... so ....)
Here is sample of the logging with this patch:
{code}
74390 2015-12-09 22:41:35,584 TRACE [localhost:62928.activeMasterManager] core.Tracer: Pushing TraceScope(tracerId=hconnection-0x7b764474, span={"a":"786592075da52dd103a5b53b4b9e473b","b":1449729695584,"d":"HFileReaderImpl.readBlock","r":"hconnection-0x7b764474","p":["786592075da52dd1b93b4c359c1f08f1"]}, detached=false)
74391 java.lang.Exception
74392 at org.apache.htrace.core.Tracer$ThreadContext.pushNewScope(Tracer.java:199)
74393 at org.apache.htrace.core.Tracer.newScopeImpl(Tracer.java:326)
74394 at org.apache.htrace.core.Tracer.newScope(Tracer.java:403)
74395 at org.apache.hadoop.hbase.io.hfile.HFileReaderImpl.readBlock(HFileReaderImpl.java:1467)
74396 at org.apache.hadoop.hbase.io.hfile.CompoundBloomFilter.checkContains(CompoundBloomFilter.java:114)
74397 at org.apache.hadoop.hbase.io.hfile.CompoundBloomFilter.contains(CompoundBloomFilter.java:103)
74398 at org.apache.hadoop.hbase.regionserver.StoreFile$Reader.checkGeneralBloomFilter(StoreFile.java:1493)
74399 at org.apache.hadoop.hbase.regionserver.StoreFile$Reader.passesGeneralRowBloomFilter(StoreFile.java:1415)
74400 at org.apache.hadoop.hbase.regionserver.StoreFile$Reader.passesBloomFilter(StoreFile.java:1343)
74401 at org.apache.hadoop.hbase.regionserver.StoreFileScanner.shouldUseScanner(StoreFileScanner.java:435)
74402 at org.apache.hadoop.hbase.regionserver.StoreScanner.selectScannersFrom(StoreScanner.java:397)
74403 at org.apache.hadoop.hbase.regionserver.StoreScanner.getScannersNoCompaction(StoreScanner.java:316)
74404 at org.apache.hadoop.hbase.regionserver.StoreScanner.<init>(StoreScanner.java:196)
74405 at org.apache.hadoop.hbase.regionserver.HStore.createScanner(HStore.java:1916)
74406 at org.apache.hadoop.hbase.regionserver.HStore.getScanner(HStore.java:1906)
74407 at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.<init>(HRegion.java:5580)
74408 at org.apache.hadoop.hbase.regionserver.HRegion.instantiateRegionScanner(HRegion.java:2610)
74409 at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2596)
74410 at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2577)
74411 at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2573)
74412 at org.apache.hadoop.hbase.regionserver.HRegion.get(HRegion.java:6738)
74413 at org.apache.hadoop.hbase.regionserver.HRegion.get(HRegion.java:6703)
74414 at org.apache.hadoop.hbase.regionserver.RSRpcServices.get(RSRpcServices.java:2007)
74415 at org.apache.hadoop.hbase.client.HTable$1.call(HTable.java:446)
74416 at org.apache.hadoop.hbase.client.HTable$1.call(HTable.java:436)
74417 at org.apache.hadoop.hbase.client.RpcRetryingCallerImpl.callWithRetries(RpcRetryingCallerImpl.java:118)
74418 at org.apache.hadoop.hbase.client.HTable.get(HTable.java:454)
74419 at org.apache.hadoop.hbase.client.HTable.get(HTable.java:414)
74420 at org.apache.hadoop.hbase.master.TableNamespaceManager.get(TableNamespaceManager.java:178)
74421 at org.apache.hadoop.hbase.master.TableNamespaceManager.isTableAvailableAndInitialized(TableNamespaceManager.java:295)
74422 at org.apache.hadoop.hbase.master.TableNamespaceManager.start(TableNamespaceManager.java:116)
74423 at org.apache.hadoop.hbase.master.HMaster.initNamespace(HMaster.java:971)
74424 at org.apache.hadoop.hbase.master.HMaster.finishActiveMasterInitialization(HMaster.java:786)
74425 at org.apache.hadoop.hbase.master.HMaster.access$500(HMaster.java:188)
74426 at org.apache.hadoop.hbase.master.HMaster$1.run(HMaster.java:1767)
74427 at org.apache.htrace.core.TraceRunnable.run(TraceRunnable.java:45)
74428 at java.lang.Thread.run(Thread.java:744)
74429 2015-12-09 22:41:35,585 TRACE [localhost:62928.activeMasterManager] core.Tracer: Popping
74430 java.lang.Exception
74431 at org.apache.htrace.core.Tracer$ThreadContext.popScope(Tracer.java:206)
74432 at org.apache.htrace.core.Tracer.closeScope(Tracer.java:601)
74433 at org.apache.htrace.core.TraceScope.close(TraceScope.java:111)
74434 at org.apache.hadoop.hbase.io.hfile.HFileReaderImpl.readBlock(HFileReaderImpl.java:1532)
74435 at org.apache.hadoop.hbase.io.hfile.CompoundBloomFilter.checkContains(CompoundBloomFilter.java:114)
74436 at org.apache.hadoop.hbase.io.hfile.CompoundBloomFilter.contains(CompoundBloomFilter.java:103)
74437 at org.apache.hadoop.hbase.regionserver.StoreFile$Reader.checkGeneralBloomFilter(StoreFile.java:1493)
74438 at org.apache.hadoop.hbase.regionserver.StoreFile$Reader.passesGeneralRowBloomFilter(StoreFile.java:1415)
74439 at org.apache.hadoop.hbase.regionserver.StoreFile$Reader.passesBloomFilter(StoreFile.java:1343)
74440 at org.apache.hadoop.hbase.regionserver.StoreFileScanner.shouldUseScanner(StoreFileScanner.java:435)
74441 at org.apache.hadoop.hbase.regionserver.StoreScanner.selectScannersFrom(StoreScanner.java:397)
74442 at org.apache.hadoop.hbase.regionserver.StoreScanner.getScannersNoCompaction(StoreScanner.java:316)
74443 at org.apache.hadoop.hbase.regionserver.StoreScanner.<init>(StoreScanner.java:196)
74444 at org.apache.hadoop.hbase.regionserver.HStore.createScanner(HStore.java:1916)
74445 at org.apache.hadoop.hbase.regionserver.HStore.getScanner(HStore.java:1906)
74446 at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.<init>(HRegion.java:5580)
74447 at org.apache.hadoop.hbase.regionserver.HRegion.instantiateRegionScanner(HRegion.java:2610)
74448 at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2596)
74449 at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2577)
74450 at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:2573)
74451 at org.apache.hadoop.hbase.regionserver.HRegion.get(HRegion.java:6738)
74452 at org.apache.hadoop.hbase.regionserver.HRegion.get(HRegion.java:6703)
74453 at org.apache.hadoop.hbase.regionserver.RSRpcServices.get(RSRpcServices.java:2007)
74454 at org.apache.hadoop.hbase.client.HTable$1.call(HTable.java:446)
74455 at org.apache.hadoop.hbase.client.HTable$1.call(HTable.java:436)
74456 at org.apache.hadoop.hbase.client.RpcRetryingCallerImpl.callWithRetries(RpcRetryingCallerImpl.java:118)
74457 at org.apache.hadoop.hbase.client.HTable.get(HTable.java:454)
74458 at org.apache.hadoop.hbase.client.HTable.get(HTable.java:414)
74459 at org.apache.hadoop.hbase.master.TableNamespaceManager.get(TableNamespaceManager.java:178)
74460 at org.apache.hadoop.hbase.master.TableNamespaceManager.isTableAvailableAndInitialized(TableNamespaceManager.java:295)
74461 at org.apache.hadoop.hbase.master.TableNamespaceManager.start(TableNamespaceManager.java:116)
74462 at org.apache.hadoop.hbase.master.HMaster.initNamespace(HMaster.java:971)
74463 at org.apache.hadoop.hbase.master.HMaster.finishActiveMasterInitialization(HMaster.java:786)
74464 at org.apache.hadoop.hbase.master.HMaster.access$500(HMaster.java:188)
{code}
> Add to Tracer, TRACE-level logging of push and pop of contexts to aid debugging "Can't close TraceScope.."
> ----------------------------------------------------------------------------------------------------------
>
> Key: HTRACE-330
> URL: https://issues.apache.org/jira/browse/HTRACE-330
> Project: HTrace
> Issue Type: Improvement
> Reporter: stack
> Attachments: trace.push.pop.logging.patch
>
>
> Allow logging of push and pop of tracing scopes. Helps debug these kind of complaints:
> {code}
> 74546 2015-12-09 22:41:35,588 FATAL [localhost:62928.activeMasterManager] master.HMaster: Failed to become active master
> 74547 java.lang.RuntimeException: Can't close TraceScope for {"a":"786592075da52dd193e82c3df8462a4a","b":1449729695240,"d":"get","r":"hconnection-0x7b764474","p":["786592075da52dd125a2fdf5331a5961"]} because it is not the current TraceScope, {"a":"786592075da52dd1b93b4c359c1f08f1","b":1449729695565,"d":"hbase:meta","r":"hconnection-0x7b764474","p":["786592075da5 2dd193e82c3df8462a4a"],"t":[{"t":1449729695584,"m":"Creating MemStoreScanner"}]}, in thread localhost:62928.activeMasterManager
> 74548 at org.apache.htrace.core.Tracer.throwClientError(Tracer.java:278)
> 74549 at org.apache.htrace.core.Tracer.closeScope(Tracer.java:588)
> 74550 at org.apache.htrace.core.TraceScope.close(TraceScope.java:111)
> 74551 at org.apache.hadoop.hbase.client.HTable.get(HTable.java:467)
> 74552 at org.apache.hadoop.hbase.client.HTable.get(HTable.java:414)
> 74553 at org.apache.hadoop.hbase.master.TableNamespaceManager.get(TableNamespaceManager.java:178)
> 74554 at org.apache.hadoop.hbase.master.TableNamespaceManager.isTableAvailableAndInitialized(TableNamespaceManager.java:295)
> 74555 at org.apache.hadoop.hbase.master.TableNamespaceManager.start(TableNamespaceManager.java:116)
> 74556 at org.apache.hadoop.hbase.master.HMaster.initNamespace(HMaster.java:971)
> 74557 at org.apache.hadoop.hbase.master.HMaster.finishActiveMasterInitialization(HMaster.java:786)
> 74558 at org.apache.hadoop.hbase.master.HMaster.access$500(HMaster.java:188)
> 74559 at org.apache.hadoop.hbase.master.HMaster$1.run(HMaster.java:1767)
> 74560 at org.apache.htrace.core.TraceRunnable.run(TraceRunnable.java:45)
> 74561 at java.lang.Thread.run(Thread.java:744)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)