From a252ec617841b62345bcc62c8cc8bb3a25a3da7c Mon Sep 17 00:00:00 2001 From: Armin Date: Fri, 8 Sep 2017 08:02:03 +0200 Subject: [PATCH] #8172 Move timestamp handling for metrics to java.lang.System.nano_time Fixes #8180 --- logstash-core/lib/logstash/filter_delegator.rb | 4 ++-- .../lib/logstash/instrument/wrapped_write_client.rb | 6 +++--- logstash-core/lib/logstash/output_delegator.rb | 4 ++-- logstash-core/lib/logstash/util/wrapped_acked_queue.rb | 4 ++-- .../lib/logstash/util/wrapped_synchronous_queue.rb | 4 ++-- 5 files changed, 11 insertions(+), 11 deletions(-) diff --git a/logstash-core/lib/logstash/filter_delegator.rb b/logstash-core/lib/logstash/filter_delegator.rb index 96ad8e501..9040482dd 100644 --- a/logstash-core/lib/logstash/filter_delegator.rb +++ b/logstash-core/lib/logstash/filter_delegator.rb @@ -44,9 +44,9 @@ module LogStash def multi_filter(events) @metric_events_in.increment(events.size) - start_time = java.lang.System.current_time_millis + start_time = java.lang.System.nano_time new_events = @filter.multi_filter(events) - @metric_events_time.increment(java.lang.System.current_time_millis - start_time) + @metric_events_time.increment((java.lang.System.nano_time - start_time) / 1_000_000) # There is no guarantee in the context of filter # that EVENTS_IN == EVENTS_OUT, see the aggregates and diff --git a/logstash-core/lib/logstash/instrument/wrapped_write_client.rb b/logstash-core/lib/logstash/instrument/wrapped_write_client.rb index 82f0539e2..a350e84ff 100644 --- a/logstash-core/lib/logstash/instrument/wrapped_write_client.rb +++ b/logstash-core/lib/logstash/instrument/wrapped_write_client.rb @@ -25,7 +25,7 @@ module LogStash module Instrument def push(event) increment_counters(1) - start_time = java.lang.System.current_time_millis + start_time = java.lang.System.nano_time result = @write_client.push(event) report_execution_time(start_time) result @@ -35,7 +35,7 @@ module LogStash module Instrument def push_batch(batch) increment_counters(batch.size) - start_time = java.lang.System.current_time_millis + start_time = java.lang.System.nano_time result = @write_client.push_batch(batch) report_execution_time(start_time) result @@ -50,7 +50,7 @@ module LogStash module Instrument end def report_execution_time(start_time) - execution_time = java.lang.System.current_time_millis - start_time + execution_time = (java.lang.System.nano_time - start_time) / 1_000_000 @events_metrics_time.increment(execution_time) @pipeline_metrics_time.increment(execution_time) @plugin_events_metrics_time.increment(execution_time) diff --git a/logstash-core/lib/logstash/output_delegator.rb b/logstash-core/lib/logstash/output_delegator.rb index dba5fbd01..2ce8a8aba 100644 --- a/logstash-core/lib/logstash/output_delegator.rb +++ b/logstash-core/lib/logstash/output_delegator.rb @@ -45,9 +45,9 @@ module LogStash class OutputDelegator def multi_receive(events) @in_counter.increment(events.length) - start_time = java.lang.System.current_time_millis + start_time = java.lang.System.nano_time @strategy.multi_receive(events) - @time_metric.increment(java.lang.System.current_time_millis - start_time) + @time_metric.increment((java.lang.System.nano_time - start_time) / 1_000_000) @out_counter.increment(events.length) end diff --git a/logstash-core/lib/logstash/util/wrapped_acked_queue.rb b/logstash-core/lib/logstash/util/wrapped_acked_queue.rb index 74b7f76ea..59a57e42e 100644 --- a/logstash-core/lib/logstash/util/wrapped_acked_queue.rb +++ b/logstash-core/lib/logstash/util/wrapped_acked_queue.rb @@ -205,7 +205,7 @@ module LogStash; module Util end def start_clock - @inflight_clocks[Thread.current] = java.lang.System.current_time_millis + @inflight_clocks[Thread.current] = java.lang.System.nano_time end def stop_clock(batch) @@ -214,7 +214,7 @@ module LogStash; module Util # only stop (which also records) the metrics if the batch is non-empty. # start_clock is now called at empty batch creation and an empty batch could # stay empty all the way down to the close_batch call. - time_taken = java.lang.System.current_time_millis - @inflight_clocks[Thread.current] + time_taken = (java.lang.System.nano_time - @inflight_clocks[Thread.current]) / 1_000_000 @event_metric.report_time(:duration_in_millis, time_taken) @pipeline_metric.report_time(:duration_in_millis, time_taken) end diff --git a/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb b/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb index ebe0379a4..a7532cdf6 100644 --- a/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb +++ b/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb @@ -144,7 +144,7 @@ module LogStash; module Util end def start_clock - @inflight_clocks[Thread.current] = java.lang.System.current_time_millis + @inflight_clocks[Thread.current] = java.lang.System.nano_time end def stop_clock(batch) @@ -153,7 +153,7 @@ module LogStash; module Util # only stop (which also records) the metrics if the batch is non-empty. # start_clock is now called at empty batch creation and an empty batch could # stay empty all the way down to the close_batch call. - time_taken = java.lang.System.current_time_millis - @inflight_clocks[Thread.current] + time_taken = (java.lang.System.nano_time - @inflight_clocks[Thread.current]) / 1_000_000 @event_metric_time.increment(time_taken) @pipeline_metric_time.increment(time_taken) end