Add some deprecation optimizations #37597

jasontedor · 2019-01-18T03:40:03Z

This commit optimizes some of the performance issues from using deprecation logging:

we optimize encoding the deprecation value
we optimize formatting the deprecation string
we optimize away getting the current time (by using cached startup time)

This commit optimizes some of the performance issues from using deprecation logging: - we optimize encoding the deprecation value - we optimize formatting the deprecation string - we optimize away getting the current time (by using cached startup time)

elasticmachine · 2019-01-18T03:40:05Z

Pinging @elastic/es-core-infra

jasontedor · 2019-01-18T03:41:15Z

This PR together with #37590 reduces the penalty seen in #35754 on my machine from 40x to 10x. The big remaining issue to address is the expensiveness of de-duplicating the warning headers as outlined in #37530.

rjernst

LGTM

jasontedor · 2019-01-18T04:27:10Z

@elasticmachine run gradle build tests 1
@elasticmachine run gradle build tests 2

danielmitterdorfer

Thanks for tackling this. I left a few comments.

danielmitterdorfer · 2019-01-18T06:43:54Z

server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java

+         * We want a fast path check to avoid creating the string builder and copying characters if needed. So we walk the string looking
+         * for either of the characters that we need to escape. If we find a character that needs escaping, we start over and
+         */
+        boolean encodingNeeded = false;


I think this variable should be name escapingNeeded as this method is concerned with escaping special characters but not encoding (which is done separately)?

I pushed 17646cf.

danielmitterdorfer · 2019-01-18T06:46:25Z

server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java

-        return String.format(Locale.ROOT, WARNING_FORMAT, escapeAndEncode(s), RFC_7231_DATE_TIME.format(ZonedDateTime.now(GMT)));
+        return WARNING_PREFIX + " "
+                + "\"" + escapeAndEncode(s) + "\"" + " "
+                + "\"" + STARTUP_TIME + "\"";


maybe rewrite as

return WARNING_PREFIX + " \"" + escapeAndEncode(s) + "\" \"" + STARTUP_TIME + "\"";

Or did you think it is too subtle to miss the required spaces in between? Either way, I don't feel too strongly about it.

Yes, what is here is clearer IMO, and the compiler will fold the constants anyway (so fold " " and "\"" into " \"", and "\"" and " " and "\"" into "\" \"" so that the number of invocations to StringBuilder#append will be reduced).

Fine with me.

danielmitterdorfer · 2019-01-18T06:48:17Z

server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java

-        return String.format(Locale.ROOT, WARNING_FORMAT, escapeAndEncode(s), RFC_7231_DATE_TIME.format(ZonedDateTime.now(GMT)));
+        return WARNING_PREFIX + " "
+                + "\"" + escapeAndEncode(s) + "\"" + " "
+                + "\"" + STARTUP_TIME + "\"";


I also find it a bit odd to always use STARTUP_TIME as the value for warn-date but on the other hand I did not find anything in RFC 7234 that forbids doing that.

Ultimately I want to remove the warn-date from the header. It's not required by the specification (it's optional). However, removing it requires coordinating with Kibana which parses these warning headers for displaying in Console (elastic/kibana#10470). So here I eliminate the performance issue to show the advantages (otherwise, it does show up in profiling output, ~15%).

I'm fine with that, it just puzzled me in the beginning.

I opened elastic/kibana#28995

danielmitterdorfer · 2019-01-18T06:57:47Z

server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java

@@ -157,14 +157,13 @@ public void deprecatedAndMaybeLog(final String key, final String msg, final Obje
     * arbitrary token; here we use the Elasticsearch version and build hash. The warn text must be quoted. The warn-date is an optional
     * quoted field that can be in a variety of specified date formats; here we use RFC 1123 format.


Only semi-related to your PR but I think the RFC mentioned in this comment is wrong and it should say "RFC 7231 format" instead of "RFC 1123 format".

danielmitterdorfer · 2019-01-18T07:05:56Z

server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java

@@ -339,7 +338,9 @@ public Void run() {
     * @return a warning value formatted according to RFC 7234
     */
    public static String formatWarning(final String s) {
-        return String.format(Locale.ROOT, WARNING_FORMAT, escapeAndEncode(s), RFC_7231_DATE_TIME.format(ZonedDateTime.now(GMT)));
+        return WARNING_PREFIX + " "
+                + "\"" + escapeAndEncode(s) + "\"" + " "


Unrelated to your PR: While I am not aware that any RFC specifies a maximum field length for HTTP headers there are practical limits and I wonder whether we should enforce one (in a follow-up) as deprecation messages might be long?

danielmitterdorfer

LGTM

jasontedor · 2019-01-18T15:26:41Z

@elasticmachine run gradle build tests 2

jasontedor · 2019-01-18T17:03:38Z

@elasticmachine run gradle build tests 2

jasontedor · 2019-01-18T18:50:28Z

@elasticmachine run gradle builds tests 2

jasontedor · 2019-01-18T18:51:45Z

@elasticmachine run gradle build tests 2

jasontedor · 2019-01-18T19:31:08Z

@elasticmachine run gradle build tests 2

This commit optimizes some of the performance issues from using deprecation logging: - we optimize encoding the deprecation value - we optimize formatting the deprecation string - we optimize away getting the current time (by using cached startup time)

* elastic/master: (104 commits) Permission for restricted indices (elastic#37577) Remove Watcher Account "unsecure" settings (elastic#36736) Add cache cleaning task for ML snapshot (elastic#37505) Update jdk used by the docker builds (elastic#37621) Remove an unused constant in PutMappingRequest. Update get users to allow unknown fields (elastic#37593) Do not add index event listener if CCR disabled (elastic#37432) Add local session timeouts to leader node (elastic#37438) Add some deprecation optimizations (elastic#37597) refactor inner geogrid classes to own class files (elastic#37596) Remove obsolete deprecation checks (elastic#37510) ML: Add support for single bucket aggs in Datafeeds (elastic#37544) ML: creating ML State write alias and pointing writes there (elastic#37483) Deprecate types in the put mapping API. (elastic#37280) [ILM] Add unfollow action (elastic#36970) Packaging: Update marker used to allow ELASTIC_PASSWORD (elastic#37243) Fix setting openldap realm ssl config Document the need for JAVA11_HOME (elastic#37589) SQL: fix object extraction from sources (elastic#37502) Nit in settings.gradle for Eclipse ...

s1monw · 2019-01-21T12:28:28Z

server/src/main/java/org/elasticsearch/common/logging/DeprecationLogger.java

@@ -384,7 +409,7 @@ static String escapeBackslashesAndQuotes(final String s) {
        for (int i = 0x80; i <= 0xFF; i++) {
            doesNotNeedEncoding.set(i);
        }
-        assert !doesNotNeedEncoding.get('%');
+        assert doesNotNeedEncoding.get('%') == false : doesNotNeedEncoding;


jasontedor added 3 commits January 17, 2019 22:36

Remove unnecessary field

25d0348

Remove another unnecessary field

82ecbc7

jasontedor added >enhancement :Core/Infra/Logging Log management and logging utilities v7.0.0 v6.7.0 labels Jan 18, 2019

jasontedor requested review from rjernst and danielmitterdorfer January 18, 2019 03:40

Fix missing quote

8ef7ff2

rjernst approved these changes Jan 18, 2019

View reviewed changes

This was referenced Jan 18, 2019

DeprecationLogger's deduplication performance #37530

Closed

Script queries using joda time getMillis() slower than using java time toInstant().toEpochMilli() #35754

Closed

danielmitterdorfer reviewed Jan 18, 2019

View reviewed changes

Feedback

17646cf

danielmitterdorfer approved these changes Jan 18, 2019

View reviewed changes

jasontedor mentioned this pull request Jan 18, 2019

Make the date in warnings optional for Console elastic/kibana#28995

Merged

jasontedor merged commit adae233 into elastic:master Jan 18, 2019

jasontedor deleted the some-deprecation-optimizations branch January 18, 2019 21:45

jasontedor mentioned this pull request Jan 18, 2019

Remove warn-date from warning headers #37622

Merged

s1monw reviewed Jan 21, 2019

View reviewed changes

jasontedor mentioned this pull request Jan 22, 2019

Optimize warning header de-duplication #37725

Merged

colings86 added v7.0.0-beta1 and removed v7.0.0 labels Feb 7, 2019

howardhuanghua mentioned this pull request Aug 3, 2020

Fix deperacation log backward compatibility issue. #60561

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add some deprecation optimizations #37597

Add some deprecation optimizations #37597

jasontedor commented Jan 18, 2019 •

edited

Loading

elasticmachine commented Jan 18, 2019

jasontedor commented Jan 18, 2019

rjernst left a comment

jasontedor commented Jan 18, 2019

danielmitterdorfer left a comment

danielmitterdorfer Jan 18, 2019

jasontedor Jan 18, 2019

danielmitterdorfer Jan 18, 2019

jasontedor Jan 18, 2019 •

edited

Loading

danielmitterdorfer Jan 18, 2019

danielmitterdorfer Jan 18, 2019

jasontedor Jan 18, 2019

danielmitterdorfer Jan 18, 2019

jasontedor Jan 18, 2019

danielmitterdorfer Jan 18, 2019

danielmitterdorfer Jan 18, 2019

danielmitterdorfer left a comment

jasontedor commented Jan 18, 2019

jasontedor commented Jan 18, 2019

jasontedor commented Jan 18, 2019

jasontedor commented Jan 18, 2019

jasontedor commented Jan 18, 2019

s1monw Jan 21, 2019

		@@ -157,14 +157,13 @@ public void deprecatedAndMaybeLog(final String key, final String msg, final Obje
		* arbitrary token; here we use the Elasticsearch version and build hash. The warn text must be quoted. The warn-date is an optional
		* quoted field that can be in a variety of specified date formats; here we use RFC 1123 format.

Add some deprecation optimizations #37597

Add some deprecation optimizations #37597

Conversation

jasontedor commented Jan 18, 2019 • edited Loading

elasticmachine commented Jan 18, 2019

jasontedor commented Jan 18, 2019

rjernst left a comment

Choose a reason for hiding this comment

jasontedor commented Jan 18, 2019

danielmitterdorfer left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jasontedor Jan 18, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

danielmitterdorfer left a comment

Choose a reason for hiding this comment

jasontedor commented Jan 18, 2019

jasontedor commented Jan 18, 2019

jasontedor commented Jan 18, 2019

jasontedor commented Jan 18, 2019

jasontedor commented Jan 18, 2019

Choose a reason for hiding this comment

jasontedor commented Jan 18, 2019 •

edited

Loading

jasontedor Jan 18, 2019 •

edited

Loading