You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cassandra.apache.org by "Pedro Gordo (JIRA)" <ji...@apache.org> on 2018/01/18 22:25:00 UTC
[jira] [Commented] (CASSANDRA-12750) TRACE messages get dropped
[ https://issues.apache.org/jira/browse/CASSANDRA-12750?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16331346#comment-16331346 ]
Pedro Gordo commented on CASSANDRA-12750:
-----------------------------------------
If you run the same query from within cqlsh (with tracing on), do you get a message of the sort:
{{Trace session id: blablabla [more] Unable to retrieve Query Trace information [more]}} ?
> TRACE messages get dropped
> --------------------------
>
> Key: CASSANDRA-12750
> URL: https://issues.apache.org/jira/browse/CASSANDRA-12750
> Project: Cassandra
> Issue Type: Bug
> Components: Local Write-Read Paths, Observability
> Environment: Ubuntu 14.04 LTS
> Reporter: Kuku1
> Priority: Major
>
> Two of my nodes drop TRACE messages for some reason.
> I'm using Cassandra 3.0.8.
> I'm running a "select * from ... " query that will return 300.000 rows. I want to measure the total query runtime.
> My application runs the following code.
> {code}
> PreparedStatement preparedStatement = connection.prepareStatement(query).enableTracing();
> if (preparedStatement == null) {
> return;
> }
> BoundStatement bs = preparedStatement.bind();
> ResultSet rs = connection.execute(bs);
> while (!rs.isFullyFetched()) {
> rs.fetchMoreResults();
> }
> //all results have been fetched at this point
> //sleep 15s to wait for C* to write the query traces
> Thread.sleep(15000);
> long totalQueryRuntime = 0;
> List<ExecutionInfo> executionInfos = rs.getAllExecutionInfo();
> for (ExecutionInfo ex : executionInfos) {
> QueryTrace queryTrace = ex.getQueryTrace();
> totalQueryRuntime += queryTrace.getDurationMicros();
> if (verbose) {
> for (Event event : queryTrace.getEvents()) {
> //some logging
> }
> }
> }
> {code}
> The application fails with this exception:
> {code}
> com.datastax.driver.core.exceptions.TraceRetrievalException: Unable to retrieve complete query trace for id 88dae7d0-8ada-11e6-9f80-d9082a06988f after 5 tries
> at com.datastax.driver.core.QueryTrace.doFetchTrace(QueryTrace.java:228)
> at com.datastax.driver.core.QueryTrace.maybeFetchTrace(QueryTrace.java:177)
> at com.datastax.driver.core.QueryTrace.getDurationMicros(QueryTrace.java:103)
> {code}
> In my system.logs, I can find these output (similar) on two of my six nodes:
> {code}
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,650 MessagingService.java:983 - _TRACE messages were dropped in last 5000 ms: 511 for internal timeout and 0 for cross node timeout
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,651 StatusLogger.java:52 - Pool Name Active Pending Completed Blocked All Time Blocked
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,657 StatusLogger.java:56 - MutationStage 0 0 35036 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,658 StatusLogger.java:56 - ViewMutationStage 0 0 0 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,658 StatusLogger.java:56 - ReadStage 0 0 399 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,659 StatusLogger.java:56 - RequestResponseStage 0 0 7158 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,659 StatusLogger.java:56 - ReadRepairStage 0 0 2 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,660 StatusLogger.java:56 - CounterMutationStage 0 0 0 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,661 StatusLogger.java:56 - MiscStage 0 0 0 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,661 StatusLogger.java:56 - CompactionExecutor 0 0 52 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,662 StatusLogger.java:56 - MemtableReclaimMemory 0 0 21 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,662 StatusLogger.java:56 - PendingRangeCalculator 0 0 8 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,663 StatusLogger.java:56 - GossipStage 0 0 476 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,663 StatusLogger.java:56 - SecondaryIndexManagement 0 0 0 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,664 StatusLogger.java:56 - HintsDispatcher 0 0 0 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,664 StatusLogger.java:56 - MigrationStage 0 0 0 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,665 StatusLogger.java:56 - MemtablePostFlush 0 0 40 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,666 StatusLogger.java:56 - ValidationExecutor 0 0 0 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,666 StatusLogger.java:56 - Sampler 0 0 0 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,667 StatusLogger.java:56 - MemtableFlushWriter 0 0 21 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,668 StatusLogger.java:56 - InternalResponseStage 0 0 0 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,669 StatusLogger.java:56 - AntiEntropyStage 0 0 0 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,670 StatusLogger.java:56 - CacheCleanupExecutor 0 0 0 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,671 StatusLogger.java:56 - Native-Transport-Requests 0 0 116 0 0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,671 StatusLogger.java:66 - CompactionManager 0 1
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,671 StatusLogger.java:78 - MessagingService n/a 0/0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,671 StatusLogger.java:88 - Cache Type Size Capacity KeysToSave
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,671 StatusLogger.java:90 - KeyCache 3160 104857600 all
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,671 StatusLogger.java:96 - RowCache 0 0 all
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,672 StatusLogger.java:103 - Table Memtable ops,data
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,672 StatusLogger.java:106 - system_distributed.parent_repair_history 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,672 StatusLogger.java:106 - system_distributed.repair_history 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,672 StatusLogger.java:106 - system.compaction_history 2,384
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,672 StatusLogger.java:106 - system.hints 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,672 StatusLogger.java:106 - system.schema_aggregates 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,673 StatusLogger.java:106 - system.IndexInfo 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,673 StatusLogger.java:106 - system.schema_columnfamilies 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,673 StatusLogger.java:106 - system.schema_triggers 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,673 StatusLogger.java:106 - system.size_estimates 2120,252650
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,673 StatusLogger.java:106 - system.schema_functions 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,673 StatusLogger.java:106 - system.paxos 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,673 StatusLogger.java:106 - system.views_builds_in_progress 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,673 StatusLogger.java:106 - system.built_views 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,674 StatusLogger.java:106 - system.peer_events 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,674 StatusLogger.java:106 - system.range_xfers 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,674 StatusLogger.java:106 - system.peers 97,46227
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,674 StatusLogger.java:106 - system.batches 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,674 StatusLogger.java:106 - system.schema_keyspaces 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,674 StatusLogger.java:106 - system.schema_usertypes 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,674 StatusLogger.java:106 - system.local 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,675 StatusLogger.java:106 - system.sstable_activity 28,1100
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,675 StatusLogger.java:106 - system.available_ranges 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,675 StatusLogger.java:106 - system.batchlog 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,675 StatusLogger.java:106 - system.schema_columns 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,675 StatusLogger.java:106 - fleetstream.data 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,675 StatusLogger.java:106 - system_schema.columns 168,25858
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,675 StatusLogger.java:106 - system_schema.types 2,16
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,675 StatusLogger.java:106 - system_schema.indexes 2,16
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,676 StatusLogger.java:106 - system_schema.keyspaces 4,242
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,676 StatusLogger.java:106 - system_schema.dropped_columns 2,16
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,676 StatusLogger.java:106 - system_schema.aggregates 2,16
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,676 StatusLogger.java:106 - system_schema.triggers 2,16
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,676 StatusLogger.java:106 - system_schema.tables 27,17400
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,676 StatusLogger.java:106 - system_schema.views 2,16
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,676 StatusLogger.java:106 - system_schema.functions 2,16
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,677 StatusLogger.java:106 - test.data 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,677 StatusLogger.java:106 - system_auth.roles 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,677 StatusLogger.java:106 - system_auth.role_members 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,677 StatusLogger.java:106 - system_auth.resource_role_permissons_index 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,677 StatusLogger.java:106 - system_auth.role_permissions 0,0
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,677 StatusLogger.java:106 - system_traces.sessions 58,9106
> INFO [ScheduledTasks:1] 2016-10-05 12:51:47,677 StatusLogger.java:106 - system_traces.events 320,62299
> {code}
> nodetool tpstats on one of the two nodes that drop the traces shows:
> {code}
> nodetool tpstats
> Pool Name Active Pending Completed Blocked All time blocked
> MutationStage 0 0 32911 0 0
> ViewMutationStage 0 0 0 0 0
> ReadStage 0 0 1065 0 0
> RequestResponseStage 0 0 10969 0 0
> ReadRepairStage 0 0 6 0 0
> CounterMutationStage 0 0 0 0 0
> MiscStage 0 0 0 0 0
> CompactionExecutor 0 0 972 0 0
> MemtableReclaimMemory 0 0 21 0 0
> PendingRangeCalculator 0 0 7 0 0
> GossipStage 0 0 6278 0 0
> SecondaryIndexManagement 0 0 0 0 0
> HintsDispatcher 0 0 0 0 0
> MigrationStage 0 0 0 0 0
> MemtablePostFlush 0 0 40 0 0
> ValidationExecutor 0 0 0 0 0
> Sampler 0 0 0 0 0
> MemtableFlushWriter 0 0 21 0 0
> InternalResponseStage 0 0 0 0 0
> AntiEntropyStage 0 0 0 0 0
> CacheCleanupExecutor 0 0 0 0 0
> Native-Transport-Requests 0 0 209 0 0
> Message type Dropped
> READ 0
> RANGE_SLICE 0
> _TRACE 2789
> HINT 0
> MUTATION 0
> COUNTER_MUTATION 0
> BATCH_STORE 0
> BATCH_REMOVE 0
> REQUEST_RESPONSE 0
> PAGED_RANGE 0
> READ_REPAIR 0
> {code}
> It should not be a memory problem because my nodes have ~20GB of free RAM:
> {code}
> total used free shared buffers cached
> Mem: 49450072 27703928 21746144 944 181696 17040856
> -/+ buffers/cache: 10481376 38968696
> Swap: 50319356 148 50319208
> total used free shared buffers cached
> Mem: 49450072 30405324 19044748 1124 225256 17627620
> -/+ buffers/cache: 12552448 36897624
> Swap: 50319356 0 50319356
> {code}
> I tried with default fetchSize (5000) as well as fetchSize 50000 - both did not help. Restarting all C* services did not help either.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@cassandra.apache.org
For additional commands, e-mail: commits-help@cassandra.apache.org