[
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)
