[BUG] DLS performance has regressed with new serialization format

[peternied]

What is the bug?
Some users of OpenSearch have seen a performance decrease associated with DLS queries. Larger DLS queries (more characters)
have a larger impact.

How can one reproduce the bug?

1. Checkout my fork with the repro git clone https://github.com/peternied/security.git
2. Checkout the most recent security plugin version with the new tests git checkout dls-perf
3. Execute the new tests ./gradlew integrationTest --tests org.opensearch.security.DlsTests.testDlsLargerQueryScenarios -x jacocoTestReport
4. Open the test report ./build/reports/tests/integrationTest/classes/org.opensearch.security.DlsTests.html
5. View the standard output

Creating 5 indices with 1 document
User, Count, Avg, Max, Min, Std ms reader, 100, 11.07, 17, 8, 1.67
Attached READER with role DLS_ONLY_LONG_VALUE
User, Count, Avg, Max, Min, Std ms reader, 100, 8.45, 17, 6, 1.64
Finished checks in 5282ms
Creating 50 indices with 1 document
User, Count, Avg, Max, Min, Std ms reader, 100, 13.68, 21, 10, 2.27
Attached READER with role DLS_ONLY_LONG_VALUE
User, Count, Avg, Max, Min, Std ms reader, 100, 252.04, 538, 228, 31.20
Finished checks in 30905ms
Creating 100 indices with 1 document
User, Count, Avg, Max, Min, Std ms reader, 100, 12.56, 19, 10, 1.78
Attached READER with role DLS_ONLY_LONG_VALUE
User, Count, Avg, Max, Min, Std ms reader, 100, 984.57, 1027, 916, 21.51
Finished checks in 107909ms

What is the expected behavior?
After the DLS_ONLY_LONG_VALUE is added, the AVG should not jump up so much.

Do you have any additional context?
You can collect measures from the 2.3 build by running git checkout dls-perf from that branch to collect numbers from that version

• main...peternied:security:dls-perf
• 2.3...peternied:security:2.3-dls-perf

This issue was introduced in the following PR which did improve serialization in many scenarios, but seems to be impacting DLS queries as stored in headers.

• Improve serialization speeds #2802

[peternied]

I've tracked the problem to this serialization code that seems to take ~1ms in 2.3, whereas it takes ~13ms in 2.11

security/src/main/java/org/opensearch/security/configuration/DlsFlsValveImpl.java

Lines 455 to 461 in 6b8a3e4

	threadContext.putHeader(
	ConfigConstants.OPENDISTRO_SECURITY_DLS_QUERY_HEADER,
	Base64Helper.serializeObject((Serializable) dlsQueries)
	);
	if (log.isDebugEnabled()) {
	log.debug("attach DLS info: {}", dlsQueries);
	}

[krishna-ggk]

Is there JDK version difference between 2.3 and 2.11 in the test?

[peternied]

It uses the default JDK on your machine to specify, set export JAVA_HOME= to run the tests with different JDKs

[peternied]

Previous testing wasn't properly switching to using only the custom vs jdk (de)serializers which lead to incomplete results, its clear that the custom serialization process is producing the issue with the 981ms respond time compared to 63ms.

Test methodology

Modified Base64Helper.java by deleting other reference to Base64JDKHelper or Base64CustomHelper to force serialization process.

Ran with ./gradlew integrationTest --tests org.opensearch.security.DlsTests.testDlsLargerQueryScenarios -x jacocoTestReport

security/src/main/java/org/opensearch/security/support/Base64Helper.java

Lines 33 to 47 in 6b8a3e4

	public static String serializeObject(final Serializable object, final boolean useJDKSerialization) {
	return useJDKSerialization ? Base64JDKHelper.serializeObject(object) : Base64CustomHelper.serializeObject(object);
	}
	public static String serializeObject(final Serializable object) {
	return serializeObject(object, false);
	}
	public static Serializable deserializeObject(final String string) {
	return deserializeObject(string, false);
	}
	public static Serializable deserializeObject(final String string, final boolean useJDKDeserialization) {
	return useJDKDeserialization ? Base64JDKHelper.deserializeObject(string) : Base64CustomHelper.deserializeObject(string);
	}

Custom Serialization Enabled Results

Creating 5 indices with 1 document
User, Count, Avg, Max, Min, Std ms reader, 100, 10.45, 18, 8, 1.75
Attached READER with role DLS_ONLY_LONG_VALUE
User, Count, Avg, Max, Min, Std ms reader, 100, 8.85, 20, 6, 1.92
Finished checks in 5305ms
Creating 50 indices with 1 document
User, Count, Avg, Max, Min, Std ms reader, 100, 21.29, 310, 10, 34.49
Attached READER with role DLS_ONLY_LONG_VALUE
User, Count, Avg, Max, Min, Std ms reader, 100, 249.17, 278, 225, 9.03
Finished checks in 31874ms
Creating 100 indices with 1 document
User, Count, Avg, Max, Min, Std ms reader, 100, 12.75, 21, 10, 1.97
Attached READER with role DLS_ONLY_LONG_VALUE
User, Count, Avg, Max, Min, Std ms reader, 100, 981.53, 1050, 950, 17.50
Finished checks in 107491ms

JDK Serialization Enabled Results

Creating 5 indices with 1 document
User, Count, Avg, Max, Min, Std ms reader, 100, 11.67, 20, 9, 1.90
Attached READER with role DLS_ONLY_LONG_VALUE
User, Count, Avg, Max, Min, Std ms reader, 100, 8.62, 13, 6, 1.20
Finished checks in 5354ms
Creating 50 indices with 1 document
User, Count, Avg, Max, Min, Std ms reader, 100, 15.4, 23, 12, 2.31
Attached READER with role DLS_ONLY_LONG_VALUE
User, Count, Avg, Max, Min, Std ms reader, 100, 33.01, 81, 21, 11.79
Finished checks in 9024ms
Creating 100 indices with 1 document
User, Count, Avg, Max, Min, Std ms reader, 100, 17.73, 30, 14, 3.03
Attached READER with role DLS_ONLY_LONG_VALUE
User, Count, Avg, Max, Min, Std ms reader, 100, 63.54, 69, 59, 1.88
Finished checks in 11701ms

[peternied]

@parasjain1 - can you look into this can be setting can be disabled or fixed? I think this would justify a patch release - happy to help drive that process.

[mgodwan]

Test carried out for a map with duplicate values: https://gist.github.com/mgodwan/52801a25c13a9b0a00c6de0e7cbb0a73

The size of the data is smaller for jdk serialization as it uses ObjectOutpuStream which does not write duplicate objects again, but only handles.

I agree that it will help to have a config to control the serialization format on the fly, while also seeing if we can have same optimization of similar sense in OpenSearch core streams we use. I can create an issue for the same.

[cwperks]

Would it make sense to update the GENERIC case of serialization/de-serialization to use JDK serialization?

i.e.

For Serialization

case GENERIC:
    streamOutput.writeByte((byte) CustomSerializationFormat.GENERIC.id);
    streamOutput.writeBytes(SerializationUtils.serialize(object));
    break;

For Deserialization

case GENERIC:
    obj = SerializationUtils.deserialize(streamInput.readByteArray());
    break;

[parasjain1]

I had an idea to de-dupe the strings before serializing the objects and I ran few serialization benchmarks with this optimization for Map<String, Set> object that holds the DLS/FLS queries. The results showed that although it brought in major improvement but was still a lot slower than JDK serialization.

Sharing results below -
Test env - Mac M1 Pro (non-isolated system), JMH, JDK 11.0.7

Custom without de-dupe
 Benchmark                      (type)  Mode  Cnt          Score          Error  Units
 Base64HelperBench.deserialize     map  avgt   20  909312747.900 ± 95012981.669  ns/op
 Base64HelperBench.serialize       map  avgt   20  946489912.550 ±  7850240.160  ns/op

Custom with de-dupe
 Benchmark                      (type)  Mode   Cnt        Score       Error  Units
 Base64HelperBench.deserialize     map  avgt  1000  4494519.993 ± 17543.639  ns/op
 Base64HelperBench.serialize       map  avgt  1000  5656989.656 ± 34793.074  ns/op

JDK
 Benchmark                      (type)  Mode   Cnt       Score      Error  Units
 Base64HelperBench.deserialize     map  avgt  1000  268348.242 ± 7420.959  ns/op
 Base64HelperBench.serialize       map  avgt  1000  199770.825 ± 7573.412  ns/op