You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@druid.apache.org by GitBox <gi...@apache.org> on 2022/11/18 08:45:57 UTC
[GitHub] [druid] kaojunsong opened a new issue, #13385: Compaction task failed, how can I troubleshoot?
kaojunsong opened a new issue, #13385:
URL: https://github.com/apache/druid/issues/13385
Hi experts,
I am using druid 0.22.1, and I want to compact some small segments, so I submit a compaction task:
```
{
"type": "compact",
"dataSource": "autotest",
"ioConfig": {
"type": "compact",
"inputSpec": {
"type": "interval",
"interval": "1970-01-01T00:00:00Z/2023-11-18T07:14:34.000Z"
},
"dropExisting": true
},
"granularitySpec": {
"segmentGranularity": "MINUTE",
"queryGranularity": "MINUTE"
}
}
```
But the compaction task failed with the following status information
```
{
"id": "compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z",
"groupId": "compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z",
"type": "compact",
"createdTime": "2022-11-18T08:41:49.908Z",
"queueInsertionTime": "1970-01-01T00:00:00.000Z",
"statusCode": "FAILED",
"status": "FAILED",
"runnerStatusCode": "WAITING",
"duration": 27628,
"location": {
"host": "172.24.131.32",
"port": -1,
"tlsPort": 8100
},
"dataSource": "autotest",
"errorMsg": "Ran [1] specs, [0] succeeded, [1] failed"
}
```
And the logs:
```
{"instant":{"epochSecond":1668760935,"nanoOfSecond":19000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.storage.s3.S3DataSegmentPuller","message":"Pulling index at path[CloudObjectLocation{bucket='cerberus-zontal-ingest', path='druid/segments/autotest/2022-11-18T07:12:33.000Z_2022-11-18T07:12:34.000Z/2022-11-18T07:12:34.855Z/0/index.zip'}] to outDir[var/druid/task/compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z/work/autotest/2022-11-18T07:12:33.000Z_2022-11-18T07:12:34.000Z/2022-11-18T07:12:34.855Z/0]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760935,"nanoOfSecond":217000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.storage.s3.S3DataSegmentPuller","message":"Loaded 370186 bytes from [CloudObjectLocation{bucket='cerberus-zontal-ingest', path='druid/segments/autotest/2022-11-18T07:12:33.000Z_2022-11-18T07:12:34.000Z/2022-11-18T07:12:34.855Z/0/index.zip'}] to [/opt/druid/var/druid/task/compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z/work/autotest/2022-11-18T07:12:33.000Z_2022-11-18T07:12:34.000Z/2022-11-18T07:12:34.855Z/0]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760935,"nanoOfSecond":218000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.storage.s3.S3DataSegmentPuller","message":"Pulling index at path[CloudObjectLocation{bucket='cerberus-zontal-ingest', path='druid/segments/autotest/2022-11-18T07:12:41.000Z_2022-11-18T07:12:42.000Z/2022-11-18T07:12:42.687Z/0/index.zip'}] to outDir[var/druid/task/compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z/work/autotest/2022-11-18T07:12:41.000Z_2022-11-18T07:12:42.000Z/2022-11-18T07:12:42.687Z/0]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760935,"nanoOfSecond":318000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.storage.s3.S3DataSegmentPuller","message":"Loaded 370186 bytes from [CloudObjectLocation{bucket='cerberus-zontal-ingest', path='druid/segments/autotest/2022-11-18T07:12:41.000Z_2022-11-18T07:12:42.000Z/2022-11-18T07:12:42.687Z/0/index.zip'}] to [/opt/druid/var/druid/task/compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z/work/autotest/2022-11-18T07:12:41.000Z_2022-11-18T07:12:42.000Z/2022-11-18T07:12:42.687Z/0]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760935,"nanoOfSecond":319000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.storage.s3.S3DataSegmentPuller","message":"Pulling index at path[CloudObjectLocation{bucket='cerberus-zontal-ingest', path='druid/segments/autotest/2022-11-18T07:13:34.000Z_2022-11-18T07:13:35.000Z/2022-11-18T07:13:36.349Z/0/index.zip'}] to outDir[var/druid/task/compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z/work/autotest/2022-11-18T07:13:34.000Z_2022-11-18T07:13:35.000Z/2022-11-18T07:13:36.349Z/0]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760935,"nanoOfSecond":414000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.storage.s3.S3DataSegmentPuller","message":"Loaded 370186 bytes from [CloudObjectLocation{bucket='cerberus-zontal-ingest', path='druid/segments/autotest/2022-11-18T07:13:34.000Z_2022-11-18T07:13:35.000Z/2022-11-18T07:13:36.349Z/0/index.zip'}] to [/opt/druid/var/druid/task/compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z/work/autotest/2022-11-18T07:13:34.000Z_2022-11-18T07:13:35.000Z/2022-11-18T07:13:36.349Z/0]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760935,"nanoOfSecond":816000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.indexing.common.task.CompactionTask","message":"Generate compaction task spec with new query granularity overrided from input [{type=period, period=PT1M, timeZone=UTC, origin=null}]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":502000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.indexing.common.task.CompactionTask","message":"Generated [1] compaction task specs","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":617000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.indexing.common.task.AbstractBatchIndexTask","message":"[forceTimeChunkLock] is set to true in task context. Use timeChunk lock","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":703000000},"thread":"task-runner-0-priority-0","level":"WARN","loggerName":"org.apache.druid.indexing.common.task.CompactionTask","message":"indexSpec is not ready: [{\n \"type\" : \"index_parallel\",\n \"id\" : \"compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z\",\n \"groupId\" : \"compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z\",\n \"resource\" : {\n \"availabilityGroup\" : \"compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z\",\n \"requiredCapacity\" : 1\n },\n \"spec\" : {\n \"dataSchema\" : {\n \"dataSource\" : \"autotest\",\n \"timestampSpec\" : {\n \"column\" : \"__time\",\n \"format\" : \"millis\",\n \"missingValue\" : null\n },\n \"dimensionsSpec\" : {\n \"dimensions\" : [ {\n \"type\" : \"string\",\n \"name\" : \"content_identifier\",\n \"multiValueHandling\" : \"SORTED_ARRAY\",\n \"createBitmapIndex\" : true\n
}, {\n \"type\" : \"string\",\n \"name\" : \"information_package_iri\",\n \"multiValueHandling\" : \"SORTED_ARRAY\",\n \"createBitmapIndex\" : true\n }, {\n \"type\" : \"string\",\n \"name\" : \"iri\",\n \"multiValueHandling\" : \"SORTED_ARRAY\",\n \"createBitmapIndex\" : true\n }, {\n \"type\" : \"long\",\n \"name\" : \"x1_value_int\",\n \"multiValueHandling\" : \"SORTED_ARRAY\",\n \"createBitmapIndex\" : false\n }, {\n \"type\" : \"long\",\n \"name\" : \"y1_value_int\",\n \"multiValueHandling\" : \"SORTED_ARRAY\",\n \"createBitmapIndex\" : false\n } ],\n \"dimensionExclusions\" : [ \"__time\" ]\n },\n \"metricsSpec\" : [ ],\n \"granularitySpec\" : {\n \"type\" : \"uniform\",\n \"segmentGranularity\" : \"MINUTE\",\n \"queryGranularity\" : \"MINUTE\",\n \"rollup\
" : false,\n \"intervals\" : [ \"2022-11-17T07:51:00.000Z/2022-11-18T07:13:35.000Z\" ]\n },\n \"transformSpec\" : {\n \"filter\" : null,\n \"transforms\" : [ ]\n }\n },\n \"ioConfig\" : {\n \"type\" : \"index_parallel\",\n \"inputSource\" : {\n \"type\" : \"druid\",\n \"dataSource\" : \"autotest\",\n \"interval\" : \"1970-01-01T00:00:00.000Z/2022-11-18T07:14:34.000Z\"\n },\n \"inputFormat\" : null,\n \"appendToExisting\" : false,\n \"dropExisting\" : true\n },\n \"tuningConfig\" : {\n \"type\" : \"compaction\",\n \"maxRowsPerSegment\" : 5000000,\n \"appendableIndexSpec\" : {\n \"type\" : \"onheap\"\n },\n \"maxRowsInMemory\" : 1000000,\n \"maxBytesInMemory\" : 0,\n \"skipBytesInMemoryOverheadCheck\" : false,\n \"maxTotalRows\" : 9223372036854775807,\n \"numShards\" : null,\n \"splitHintSpec\" : null,\n \"partitionsSpec\" : {
\n \"type\" : \"dynamic\",\n \"maxRowsPerSegment\" : 5000000,\n \"maxTotalRows\" : 9223372036854775807\n },\n \"indexSpec\" : {\n \"bitmap\" : {\n \"type\" : \"roaring\",\n \"compressRunOnSerialization\" : true\n },\n \"dimensionCompression\" : \"lz4\",\n \"metricCompression\" : \"lz4\",\n \"longEncoding\" : \"longs\",\n \"segmentLoader\" : null\n },\n \"indexSpecForIntermediatePersists\" : {\n \"bitmap\" : {\n \"type\" : \"roaring\",\n \"compressRunOnSerialization\" : true\n },\n \"dimensionCompression\" : \"lz4\",\n \"metricCompression\" : \"lz4\",\n \"longEncoding\" : \"longs\",\n \"segmentLoader\" : null\n },\n \"maxPendingPersists\" : 0,\n \"forceGuaranteedRollup\" : false,\n \"reportParseExceptions\" : false,\n \"pushTimeout\" : 0,\n \"segmentWriteOutMediumFactory\" : null,\n \"maxNum
ConcurrentSubTasks\" : 1,\n \"maxRetry\" : 3,\n \"taskStatusCheckPeriodMs\" : 1000,\n \"chatHandlerTimeout\" : \"PT10S\",\n \"chatHandlerNumRetries\" : 5,\n \"maxNumSegmentsToMerge\" : 100,\n \"totalNumMergeTasks\" : 10,\n \"logParseExceptions\" : false,\n \"maxParseExceptions\" : 2147483647,\n \"maxSavedParseExceptions\" : 0,\n \"maxColumnsToMerge\" : -1,\n \"awaitSegmentAvailabilityTimeoutMillis\" : 0,\n \"partitionDimensions\" : [ ]\n }\n },\n \"context\" : {\n \"useLineageBasedSegmentAllocation\" : true,\n \"appenderatorTrackingTaskId\" : \"compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z\",\n \"storeCompactionState\" : true,\n \"forceTimeChunkLock\" : true,\n \"priority\" : 25\n },\n \"dataSource\" : \"autotest\"\n}].\nTrying the next indexSpec.","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":703000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.indexing.common.task.CompactionTask","message":"Ran [1] specs, [0] succeeded, [1] failed","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":705000000},"thread":"task-runner-0-priority-0","level":"INFO","loggerName":"org.apache.druid.indexing.worker.executor.ExecutorLifecycle","message":"Task completed with status: {\n \"id\" : \"compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z\",\n \"status\" : \"FAILED\",\n \"duration\" : 6798,\n \"errorMsg\" : \"Ran [1] specs, [0] succeeded, [1] failed\",\n \"location\" : {\n \"host\" : null,\n \"port\" : -1,\n \"tlsPort\" : -1\n }\n}","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":106,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":710000000},"thread":"main","level":"INFO","loggerName":"org.apache.druid.java.util.common.lifecycle.Lifecycle","message":"Stopping lifecycle [module] stage [ANNOUNCEMENTS]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":711000000},"thread":"main","level":"INFO","loggerName":"org.apache.druid.java.util.common.lifecycle.Lifecycle","message":"Stopping lifecycle [module] stage [SERVER]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":716000000},"thread":"main","level":"INFO","loggerName":"org.eclipse.jetty.server.AbstractConnector","message":"Stopped ServerConnector@58bad46f{SSL, (ssl, http/1.1)}{0.0.0.0:8100}","endOfBatch":false,"loggerFqcn":"org.eclipse.jetty.util.log.Slf4jLog","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":717000000},"thread":"main","level":"INFO","loggerName":"org.eclipse.jetty.server.session","message":"node0 Stopped scavenging","endOfBatch":false,"loggerFqcn":"org.eclipse.jetty.util.log.Slf4jLog","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":802000000},"thread":"main","level":"INFO","loggerName":"org.eclipse.jetty.server.handler.ContextHandler","message":"Stopped o.e.j.s.ServletContextHandler@7c4ca87c{/,null,STOPPED}","endOfBatch":false,"loggerFqcn":"org.eclipse.jetty.util.log.Slf4jLog","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":805000000},"thread":"main","level":"INFO","loggerName":"org.apache.druid.java.util.common.lifecycle.Lifecycle","message":"Stopping lifecycle [module] stage [NORMAL]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":806000000},"thread":"main","level":"INFO","loggerName":"org.apache.druid.indexing.overlord.SingleTaskBackgroundRunner","message":"Starting graceful shutdown of task[compact_autotest_ddbohokd_2022-11-18T08:41:49.906Z].","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":816000000},"thread":"LookupExtractorFactoryContainerProvider-MainThread","level":"INFO","loggerName":"org.apache.druid.query.lookup.LookupReferencesManager","message":"Lookup Management loop exited. Lookup notices are not handled anymore.","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":103,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":816000000},"thread":"main","level":"INFO","loggerName":"org.apache.druid.query.lookup.LookupReferencesManager","message":"Closed lookup [deleted_information_packages].","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760936,"nanoOfSecond":821000000},"thread":"Curator-Framework-0","level":"INFO","loggerName":"org.apache.curator.framework.imps.CuratorFrameworkImpl","message":"backgroundOperationsLoop exiting","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":99,"threadPriority":5}
{"instant":{"epochSecond":1668760937,"nanoOfSecond":18000000},"thread":"main","level":"INFO","loggerName":"org.apache.zookeeper.ZooKeeper","message":"Session: 0x1001892b7e9010b closed","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5}
{"instant":{"epochSecond":1668760937,"nanoOfSecond":18000000},"thread":"main-EventThread","level":"INFO","loggerName":"org.apache.zookeeper.ClientCnxn","message":"EventThread shut down for session: 0x1001892b7e9010b","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":98,"threadPriority":5}
{"instant":{"epochSecond":1668760937,"nanoOfSecond":105000000},"thread":"main","level":"INFO","loggerName":"org.apache.druid.java.util.common.lifecycle.Lifecycle","message":"Stopping lifecycle [module] stage [INIT]","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","threadId":1,"threadPriority":5}
Finished peon task
```
I have not found any useful information for locating the issue, can anyone help me? Or how can I troubleshout issues like this? Thanks a lot in advance.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org
[GitHub] [druid] kaojunsong commented on issue #13385: Compaction task failed, how can I troubleshoot?
Posted by GitBox <gi...@apache.org>.
kaojunsong commented on issue #13385:
URL: https://github.com/apache/druid/issues/13385#issuecomment-1319746464
I searched in the Slack, and found that someone suggest to use
```
"context": {
"forceTimeChunkLock": false
}
```
And the compaction task works after I added this setting.
But I don't know if there is any side effect if I add this setting.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org
[GitHub] [druid] gianm commented on issue #13385: Compaction task failed, how can I troubleshoot?
Posted by GitBox <gi...@apache.org>.
gianm commented on issue #13385:
URL: https://github.com/apache/druid/issues/13385#issuecomment-1321465429
The `indexSpec is not ready` warning happens if the task is unable to acquire a lock on its interval. The interval is `1970-01-01T00:00:00Z/2023-11-18T07:14:34.000Z` (from your `compact` task spec) so it would be trying to get an exclusive lock for that interval. Is it possible some other task was running at the time? If so, that would cause the behavior you saw. You can retry later when no other tasks are running.
> And the compaction task works after I added this setting.
> But I don't know if there is any side effect if I add this setting.
`forceTimeChunkLock: false` is an experimental setting which you can read more about here: https://druid.apache.org/docs/latest/ingestion/tasks.html#locking. It makes the locking more fine-grained, so avoids the lock contention issue that you are probably hitting. It is experimental, though, so I'd only recommend it if you are comfortable with a feature that is not currently viewed as production-ready.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org
[GitHub] [druid] gianm commented on issue #13385: Compaction task failed, how can I troubleshoot?
Posted by GitBox <gi...@apache.org>.
gianm commented on issue #13385:
URL: https://github.com/apache/druid/issues/13385#issuecomment-1344899824
An update — I believe this is the same bug as described here: https://github.com/apache/druid/issues/13540#issuecomment-1344899192.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org