Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add ingest_took to bulk response #16876

Merged
merged 1 commit into from Mar 1, 2016
Merged

Conversation

martijnvg
Copy link
Member

The ingest_took indicates how much time was spent on ingest preprocessing.

The ingest_took is separate from took, which keeps track how much time is spent on indexing/deleting/updating. The ingest_took is only visible in the rest response if at least one index request has ingest enabled.

@martijnvg martijnvg added >enhancement v5.0.0-alpha1 :Data Management/Ingest Node Execution or management of Ingest Pipelines including GeoIP labels Mar 1, 2016
@@ -101,6 +101,7 @@ void processIndexRequest(Task task, String action, ActionListener listener, Acti
}

void processBulkIndexRequest(Task task, BulkRequest original, String action, ActionFilterChain chain, ActionListener<BulkResponse> listener) {
long ingestStartTime = System.currentTimeMillis();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

can we use nano time?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The reason I picked System.currentTimeMillis() is because that is what the bulk api uses too. Otherwise that would be inconsistent?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

any time we measure deltas (how long something took) we should use nanoTime. currentTimeMillis can be reset by ntp ... if the bulk api uses it for this purpose, it should be fixed...

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

don't we have millis everywhere else? isn't it better to keep millis here too?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

sorry I commented before reading your answer... ignore me

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Makes sense, I can fix the bulk api to use nanoTime instead of currentTimeMillis in a separate PR.

@martijnvg
Copy link
Member Author

@javanna @bleskes I've updated the PR.

@@ -106,6 +126,7 @@ public void readFrom(StreamInput in) throws IOException {
responses[i] = BulkItemResponse.readBulkItem(in);
}
tookInMillis = in.readVLong();
ingestTookInMillis = in.readLong();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

you can sue ZLong for small values (FYI)...

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nice, I didn't know this existed.

@martijnvg martijnvg force-pushed the ingest_took branch 2 times, most recently from a9eb4e5 to 1016139 Compare March 1, 2016 15:31
@javanna
Copy link
Member

javanna commented Mar 1, 2016

LGTM

…ent on ingest preprocessing.

The `ingest_took` is separate from `took`, which keeps track how much time is spent on indexing/deleting/updating.
The `ingest_took` is only visible in the rest response if at least for one bulk item has ingest enabled.
@martijnvg martijnvg merged commit 7538700 into elastic:master Mar 1, 2016
@s1monw
Copy link
Contributor

s1monw commented Mar 2, 2016

this PR passes invalid tookInMillis values to serialization. https://github.com/elastic/elasticsearch/pull/16876/files#diff-764ab3948584e67f5cb1d566ef82186aR38 -1 is not allowed for vlong it must be positive. I have a failing test because of this:

ERROR   0.14s J1 | DecayFunctionScoreIT.testManyDocsLin <<< FAILURES!
   > Throwable #1: UncategorizedExecutionException[Failed execution]; nested: AssertionError;
   >    at __randomizedtesting.SeedInfo.seed([8A21AFDC7C31D644:E577B0C45C2FD983]:0)
   >    at org.elasticsearch.action.support.AdapterActionFuture.rethrowExecutionException(AdapterActionFuture.java:87)
   >    at org.elasticsearch.action.support.AdapterActionFuture.actionGet(AdapterActionFuture.java:46)
   >    at org.elasticsearch.test.ESIntegTestCase.indexRandom(ESIntegTestCase.java:1417)
   >    at org.elasticsearch.test.ESIntegTestCase.indexRandom(ESIntegTestCase.java:1352)
   >    at org.elasticsearch.test.ESIntegTestCase.indexRandom(ESIntegTestCase.java:1336)
   >    at org.elasticsearch.search.functionscore.DecayFunctionScoreIT.testManyDocsLin(DecayFunctionScoreIT.java:612)
   >    at java.lang.Thread.run(Thread.java:745)
   > Caused by: java.lang.AssertionError
   >    at org.elasticsearch.common.io.stream.StreamOutput.writeVLong(StreamOutput.java:198)
   >    at org.elasticsearch.action.bulk.BulkResponse.writeTo(BulkResponse.java:141)
   >    at org.elasticsearch.transport.local.LocalTransportChannel.sendResponse(LocalTransportChannel.java:82)
   >    at org.elasticsearch.transport.local.LocalTransportChannel.sendResponse(LocalTransportChannel.java:71)
   >    at org.elasticsearch.transport.DelegatingTransportChannel.sendResponse(DelegatingTransportChannel.java:58)
   >    at org.elasticsearch.transport.RequestHandlerRegistry$TransportChannelWrapper.sendResponse(RequestHandlerRegistry.java:103)
   >    at org.elasticsearch.action.support.HandledTransportAction$TransportHandler$1.onResponse(HandledTransportAction.java:58)
   >    at org.elasticsearch.action.support.HandledTransportAction$TransportHandler$1.onResponse(HandledTransportAction.java:54)
   >    at org.elasticsearch.action.support.TransportAction$ResponseFilterChain.proceed(TransportAction.java:216)
   >    at org.elasticsearch.action.ingest.IngestActionFilter.apply(IngestActionFilter.java:87)
   >    at org.elasticsearch.action.support.TransportAction$ResponseFilterChain.proceed(TransportAction.java:214)
   >    at org.elasticsearch.action.support.TransportAction$FilteredActionListener.onResponse(TransportAction.java:241)
   >    at org.elasticsearch.action.support.TransportAction$FilteredActionListener.onResponse(TransportAction.java:227)
   >    at org.elasticsearch.action.bulk.TransportBulkAction$2.finishHim(TransportBulkAction.java:355)
   >    at org.elasticsearch.action.bulk.TransportBulkAction$2.onResponse(TransportBulkAction.java:327)
   >    at org.elasticsearch.action.bulk.TransportBulkAction$2.onResponse(TransportBulkAction.java:316)
   >    at org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:91)
   >    at org.elasticsearch.action.support.TransportAction$1.onResponse(TransportAction.java:87)
   >    at org.elasticsearch.action.support.TransportAction$ResponseFilterChain.proceed(TransportAction.java:216)
   >    at org.elasticsearch.action.ingest.IngestActionFilter.apply(IngestActionFilter.java:87)
   >    at org.elasticsearch.action.support.TransportAction$ResponseFilterChain.proceed(TransportAction.java:214)
   >    at org.elasticsearch.action.support.TransportAction$FilteredActionListener.onResponse(TransportAction.java:241)
   >    at org.elasticsearch.action.support.TransportAction$FilteredActionListener.onResponse(TransportAction.java:227)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$ReroutePhase.finishOnSuccess(TransportReplicationAction.java:650)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$ReroutePhase$1.handleResponse(TransportReplicationAction.java:573)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$ReroutePhase$1.handleResponse(TransportReplicationAction.java:559)
   >    at org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleResponse(TransportService.java:759)
   >    at org.elasticsearch.transport.TransportService$DirectResponseChannel.processResponse(TransportService.java:830)
   >    at org.elasticsearch.transport.TransportService$DirectResponseChannel.sendResponse(TransportService.java:814)
   >    at org.elasticsearch.transport.TransportService$DirectResponseChannel.sendResponse(TransportService.java:804)
   >    at org.elasticsearch.transport.DelegatingTransportChannel.sendResponse(DelegatingTransportChannel.java:58)
   >    at org.elasticsearch.transport.RequestHandlerRegistry$TransportChannelWrapper.sendResponse(RequestHandlerRegistry.java:103)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$ReplicationPhase.doFinish(TransportReplicationAction.java:1107)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$ReplicationPhase.doRun(TransportReplicationAction.java:983)
   >    at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryPhase.finishAndMoveToReplication(TransportReplicationAction.java:794)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryPhase.executeLocally(TransportReplicationAction.java:725)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryPhase.doRun(TransportReplicationAction.java:711)
   >    at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryOperationTransportHandler.messageReceived(TransportReplicationAction.java:292)
   >    at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryOperationTransportHandler.messageReceived(TransportReplicationAction.java:284)
   >    at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:65)
   >    at org.elasticsearch.transport.TransportService$4.doRun(TransportService.java:361)
   >    at org.elasticsearch.common.util.concurrent.EsThreadPoolExecutor$FilterAbstractRunnable.doRun(EsThreadPoolExecutor.java:191)
   >    at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
   >    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
   >    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
   >    ... 1 more
  2> NOTE: leaving temporary files on disk at: /home/simon/projects/elasticsearch/core/build/testrun/integTest/J1/temp/org.elasticsearch.search.functionscore.DecayFunctionScoreIT_8A21AFDC7C31D644-001
  2> NOTE: test params are: codec=Asserting(Lucene54): {geo.lon=PostingsFormat(name=Asserting), loc=PostingsFormat(name=Asserting), test=PostingsFormat(name=Asserting), _field_names=PostingsFormat(name=Asserting), num=PostingsFormat(name=Asserting), _type=PostingsFormat(name=Asserting), num1=PostingsFormat(name=Asserting), geo.lat=PostingsFormat(name=Asserting), _timestamp=PostingsFormat(name=Asserting), _uid=PostingsFormat(name=Asserting), _all=PostingsFormat(name=Asserting), num2=PostingsFormat(name=Asserting)}, docValues:{geo.lon=DocValuesFormat(name=Asserting), loc=DocValuesFormat(name=Lucene54), num=DocValuesFormat(name=Lucene54), _type=DocValuesFormat(name=Lucene54), num1=DocValuesFormat(name=Asserting), geo.lat=DocValuesFormat(name=Lucene54), _timestamp=DocValuesFormat(name=Lucene54), _version=DocValuesFormat(name=Lucene54), num2=DocValuesFormat(name=Lucene54)}, sim=RandomSimilarity(queryNorm=true,coord=yes): {}, locale=uk, timezone=Europe/Oslo
  2> NOTE: Linux 3.13.0-35-generic amd64/Oracle Corporation 1.8.0_66 (64-bit)/cpus=12,threads=1,free=353590912,total=523239424
  2> NOTE: All tests run in this JVM: [SimpleVersioningIT, GetIndexIT, DecayFunctionScoreIT]
Completed [17/278] on J1 in 1.70s, 14 tests, 1 error <<< FAILURES!

@s1monw
Copy link
Contributor

s1monw commented Mar 2, 2016

argh scratch that - I misread the line...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
:Data Management/Ingest Node Execution or management of Ingest Pipelines including GeoIP >enhancement v5.0.0-alpha1
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants