diff --git a/cryptography/src/appleMain/kotlin/com/wire/kalium/cryptography/ProteusClientCoreCryptoImpl.kt b/cryptography/src/appleMain/kotlin/com/wire/kalium/cryptography/ProteusClientCoreCryptoImpl.kt index 27f355f6151..0d9cf4fa155 100644 --- a/cryptography/src/appleMain/kotlin/com/wire/kalium/cryptography/ProteusClientCoreCryptoImpl.kt +++ b/cryptography/src/appleMain/kotlin/com/wire/kalium/cryptography/ProteusClientCoreCryptoImpl.kt @@ -98,7 +98,10 @@ class ProteusClientCoreCryptoImpl private constructor(private val coreCrypto: Co override suspend fun encryptBatched(message: ByteArray, sessionIds: List): Map { return wrapException { - coreCrypto.proteusEncryptBatched(sessionIds.map { it.value }, toUByteList((message))).mapNotNull { entry -> + coreCrypto.proteusEncryptBatched( + sessionId = sessionIds.map { it.value }, + plaintext = toUByteList((message)) + ).mapNotNull { entry -> CryptoSessionId.fromEncodedString(entry.key)?.let { sessionId -> sessionId to toByteArray(entry.value) } diff --git a/cryptography/src/commonJvmAndroid/kotlin/com.wire.kalium.cryptography/ProteusClientCoreCryptoImpl.kt b/cryptography/src/commonJvmAndroid/kotlin/com.wire.kalium.cryptography/ProteusClientCoreCryptoImpl.kt index 9fbcd75953e..9a373797466 100644 --- a/cryptography/src/commonJvmAndroid/kotlin/com.wire.kalium.cryptography/ProteusClientCoreCryptoImpl.kt +++ b/cryptography/src/commonJvmAndroid/kotlin/com.wire.kalium.cryptography/ProteusClientCoreCryptoImpl.kt @@ -24,6 +24,8 @@ import com.wire.crypto.client.toByteArray import com.wire.kalium.cryptography.exceptions.ProteusException import io.ktor.util.decodeBase64Bytes import io.ktor.util.encodeBase64 +import kotlinx.coroutines.sync.Mutex +import kotlinx.coroutines.sync.withLock import java.io.File @Suppress("TooManyFunctions") @@ -31,6 +33,9 @@ class ProteusClientCoreCryptoImpl private constructor( private val coreCrypto: CoreCrypto, ) : ProteusClient { + private val mutex = Mutex() + private val existingSessionsCache = mutableSetOf() + override suspend fun close() { coreCrypto.close() } @@ -46,6 +51,7 @@ class ProteusClientCoreCryptoImpl private constructor( override suspend fun remoteFingerPrint(sessionId: CryptoSessionId): ByteArray = wrapException { coreCrypto.proteusFingerprintRemote(sessionId.value).toByteArray() } + override suspend fun getFingerprintFromPreKey(preKey: PreKeyCrypto): ByteArray = wrapException { coreCrypto.proteusFingerprintPrekeybundle(preKey.encodedData.decodeBase64Bytes()).toByteArray() } @@ -62,9 +68,16 @@ class ProteusClientCoreCryptoImpl private constructor( return wrapException { toPreKey(coreCrypto.proteusLastResortPrekeyId().toInt(), coreCrypto.proteusLastResortPrekey()) } } - override suspend fun doesSessionExist(sessionId: CryptoSessionId): Boolean { - return wrapException { + override suspend fun doesSessionExist(sessionId: CryptoSessionId): Boolean = mutex.withLock { + if (existingSessionsCache.contains(sessionId)) { + return@withLock true + } + wrapException { coreCrypto.proteusSessionExists(sessionId.value) + }.also { exists -> + if (exists) { + existingSessionsCache.add(sessionId) + } } } @@ -77,13 +90,9 @@ class ProteusClientCoreCryptoImpl private constructor( return wrapException { if (sessionExists) { - val decryptedMessage = coreCrypto.proteusDecrypt(sessionId.value, message) - coreCrypto.proteusSessionSave(sessionId.value) - decryptedMessage + coreCrypto.proteusDecrypt(sessionId.value, message) } else { - val decryptedMessage = coreCrypto.proteusSessionFromMessage(sessionId.value, message) - coreCrypto.proteusSessionSave(sessionId.value) - decryptedMessage + coreCrypto.proteusSessionFromMessage(sessionId.value, message) } } } @@ -119,7 +128,8 @@ class ProteusClientCoreCryptoImpl private constructor( } } - override suspend fun deleteSession(sessionId: CryptoSessionId) { + override suspend fun deleteSession(sessionId: CryptoSessionId) = mutex.withLock { + existingSessionsCache.remove(sessionId) wrapException { coreCrypto.proteusSessionDelete(sessionId.value) } diff --git a/docs/notebooks/README.md b/docs/notebooks/README.md new file mode 100644 index 00000000000..e23e2f87603 --- /dev/null +++ b/docs/notebooks/README.md @@ -0,0 +1,3 @@ +A place to store [Jupyter Notebook](https://jupyter.org/) files of ongoing studies. + +You can use Kotlin and run it directly in the IDE, thanks to [Kotlin Notebook](https://kotlinlang.org/docs/kotlin-notebook-overview.html). diff --git a/docs/notebooks/event-performance-investigation/PerformanceImprovements.ipynb b/docs/notebooks/event-performance-investigation/PerformanceImprovements.ipynb new file mode 100644 index 00000000000..7bc2901111d --- /dev/null +++ b/docs/notebooks/event-performance-investigation/PerformanceImprovements.ipynb @@ -0,0 +1,5158 @@ +{ + "cells": [ + { + "metadata": {}, + "cell_type": "markdown", + "source": [ + "# Event Processing Analysis\n", + "\n", + "### What's the goal?\n", + "Understand where Kalium is spending more time during event processing, in order to find possible performance improvements.\n", + "\n", + "\n", + "### Current context\n", + "- We've added [logs that measure how much time we're taking to process individual events](https://github.com/wireapp/kalium/pull/2827).\n", + "- The average time to process events oscilates every day between 368ms all the way up to 1280ms;\n", + "- 97,3% of the time spent processing events was processing end-to-end encrypted messages;\n", + "- 51% of the time spent processing messages was in order to process Text messages, even though they only account for 24,04% of the messages;\n", + "- `LastRead` is another interesting one: 18,57% of the count, but takes 24,3% of the time\n", + "\n", + "## What even is measured within \"Event Processing\"?\n", + "We measure all the time taken from the beginning of `EventReceiver.onEvent` until the event is handled completely.\n", + "For some Event Types, this can be super quick, like handling in-conversation Typing indication. Typing indication consists of just emitting to an in-memory flow and the event is fully processed.\n", + "For some events, this can be tricky. All End-To-End messages require parsing the encrypted blob, parsing the Protobuf, and then \"actually\" handling the different message types. Different message types often need completely different logic, so they can be as diverse as different event types.\n", + "\n", + "## Starting plan of action\n", + "Collect data locally, by adding more logs and generating events.\n", + "\n", + "My first fail was using an emulator. Running the debug of the Android app on the emulator resulted in nothing but weird looks. DataDog was giving hundreds of milliseconds as the average for event processing, while my emulator was taking about 20~30ms. \n", + "\n", + "How could that be? Running on an actual device – with the screen locked – made it right. An emulator has almost no apps installed competing for resources with the app being tested, and isn't prone to battery saving measures like CPU speed reduction, etc.\n", + " \n", + "## Lesson #1\n", + "We can focus on \"background performance\": receive a push notification, sync, decrypt, show notifications.\n", + "Or on \"foreground performance\": open the app, sync, decrypt, show notifications and unread indicators.\n", + "\n", + "The main difference is how the app might be subject to battery saving measures taken by the OS of a real device, and the time to perform the same actions might be completely different between the two scenarios.\n", + "Proposed action:\n", + "- Investigate further if we can add battery, back/fore-ground information, etc. to logs; This way we can track performance indication separately.\n", + "\n", + "## Keep digging \n", + "\n", + "Considering how there are multiple steps to \"event processing\", I've added logs to gather more information about these steps and their \"substeps\".\n", + "Also, considering 97,3% of the time is spent during Messages processing, I focused on these.\n", + "\n", + "Time spent during message events processing can be seen defined below in `TimeTaken`. \n", + " " + ] + }, + { + "metadata": {}, + "cell_type": "markdown", + "source": "Just adding some dependencies for manipulating data and Kotlin's datetime" + }, + { + "metadata": { + "collapsed": true, + "ExecuteTime": { + "end_time": "2024-09-02T08:30:22.641327700Z", + "start_time": "2024-09-02T08:30:19.253500300Z" + } + }, + "cell_type": "code", + "source": [ + "%use kandy\n", + "%use dataframe" + ], + "outputs": [], + "execution_count": 13 + }, + { + "metadata": { + "ExecuteTime": { + "end_time": "2024-09-02T08:30:22.690290300Z", + "start_time": "2024-09-02T08:30:22.645582300Z" + } + }, + "cell_type": "code", + "source": "@file:DependsOn(\"org.jetbrains.kotlinx:kotlinx-datetime:0.6.1\")", + "outputs": [], + "execution_count": 14 + }, + { + "metadata": {}, + "cell_type": "markdown", + "source": "Defining a way of representing event processing measurements and how to import data from the `logs`:" + }, + { + "metadata": { + "ExecuteTime": { + "end_time": "2024-09-02T08:30:23.007982300Z", + "start_time": "2024-09-02T08:30:22.695901100Z" + } + }, + "cell_type": "code", + "source": [ + "\n", + "import kotlin.time.Duration\n", + "import kotlin.time.Duration.Companion.milliseconds\n", + "\n", + "data class ProteusDecryption(\n", + " val checkingSession: Duration,\n", + " val decrypting: Duration,\n", + " val savingSession: Duration,\n", + ") {\n", + " val total: Duration = checkingSession + decrypting + savingSession\n", + "}\n", + "\n", + "data class ProcessingMessage(\n", + " /**\n", + " * Dealing with possibility of LegalHold\n", + " */\n", + " val checkingLegalhold: Duration,\n", + " /**\n", + " * Actually handling the content of the message,\n", + " * if LastRead, marking as read in the DB,\n", + " * if Text, inserting into the DB, emitting notifications,\n", + " * ...\n", + " */\n", + " val handlingMessageContent: Duration,\n", + " /**\n", + " * Other actions we take after the message is handled, like enqueueing delivery receipt\n", + " * and enqueueing message deletion if the message is SelfDeleting\n", + " */\n", + " val postHandling: Duration\n", + ") {\n", + " val total: Duration = checkingLegalhold + handlingMessageContent + postHandling\n", + "}\n", + "\n", + "data class TimeTaken(\n", + " val messageType: String,\n", + " val total: Duration,\n", + " val proteus: ProteusDecryption,\n", + " val processingMessage: ProcessingMessage\n", + ") {\n", + " /**\n", + " * Unknown time can be things like parsing the Protobuf, converting the blob from Base64, etc.\n", + " * In general: it shouldn't be slow, and it's less likely we can speed it up.\n", + " */\n", + " val unknownTime = total - proteus.total - processingMessage.total\n", + "}\n", + "\n", + "fun getDataFromLogs(logFileName: String): List {\n", + " val file = File(\"logs/$logFileName\")\n", + " val groups = file.readText().split(\"\"\"^$\"\"\".toRegex(RegexOption.MULTILINE))\n", + "\n", + " val allData = groups.map {\n", + " it.trim().split(\"\\n\").filter { it.isNotBlank() }\n", + " }.filter {\n", + " it.isNotEmpty()\n", + " }.map { lines ->\n", + " val logLine = lines[0]\n", + " val measurements = logLine.split(\";\").map { it.split(\" \").last() }\n", + " val proteusDuration = ProteusDecryption(\n", + " Duration.parse(measurements[0].trim()),\n", + " Duration.parse(measurements[1].trim()),\n", + " Duration.parse(measurements[2].trim()),\n", + " )\n", + "\n", + " val processingLine = lines[1]\n", + " val processingMeasurements = processingLine.split(\";\").map { it.split(\" \").last() }\n", + " val processingDuration = ProcessingMessage(\n", + " Duration.parse(processingMeasurements[0].trim()),\n", + " Duration.parse(processingMeasurements[1].trim()),\n", + " Duration.parse(processingMeasurements[2].trim()),\n", + " )\n", + " val mainInfo = lines[2].split(\" \")\n", + " val timeTaken = mainInfo[0].toLong().milliseconds\n", + " val messageType = mainInfo[1]\n", + " TimeTaken(messageType, timeTaken, proteusDuration, processingDuration)\n", + " }\n", + " return allData\n", + "}" + ], + "outputs": [], + "execution_count": 15 + }, + { + "metadata": {}, + "cell_type": "markdown", + "source": "Ok, so let's do a simple analysis of how much time is spent during Proteus, Message handling and other." + }, + { + "metadata": { + "ExecuteTime": { + "end_time": "2024-09-02T08:30:23.933356Z", + "start_time": "2024-09-02T08:30:23.018790400Z" + } + }, + "cell_type": "code", + "source": [ + "@file:DependsOn(\"org.jetbrains.kotlinx:kotlinx-datetime:0.6.1\")\n", + "\n", + "val initialData = getDataFromLogs(\"InitialData.txt\")\n", + "\n", + "val pairs =\n", + " initialData.map { it.proteus.total.inWholeMicroseconds to \"Proteus\" } +\n", + " initialData.map { it.processingMessage.total.inWholeMicroseconds to \"Processing\" } +\n", + " initialData.map { it.unknownTime.inWholeMicroseconds to \"Other\" }\n", + "\n", + "val value by column(pairs.map { it.first })\n", + "val stepName by column(pairs.map { it.second })\n", + "val dataSet = dataFrameOf(value, stepName)\n", + "dataSet.groupBy(stepName).aggregate {\n", + " sum(value) into \"total\"\n", + "}.plot {\n", + " pie {\n", + " slice(\"total\")\n", + " fillColor(\"stepName\")\n", + " }\n", + " layout {\n", + " title = \"Time spent unpacking and processing message events\"\n", + " style(Style.Void)\n", + " }\n", + "}" + ], + "outputs": [ + { + "data": { + "text/html": [ + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Time spent unpacking and processing message events\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " stepName\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Proteus\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Processing\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Other\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + "\n", + " " + ], + "application/plot+json": { + "output_type": "lets_plot_spec", + "output": { + "ggtitle": { + "text": "Time spent unpacking and processing message events" + }, + "mapping": {}, + "data": { + "total": [ + 3753588.0, + 4459976.0, + 804380.0 + ], + "stepName": [ + "Proteus", + "Processing", + "Other" + ] + }, + "kind": "plot", + "scales": [ + { + "aesthetic": "fill", + "discrete": true + } + ], + "layers": [ + { + "mapping": { + "slice": "total", + "fill": "stepName" + }, + "stat": "identity", + "sampling": "none", + "position": "identity", + "geom": "pie" + } + ], + "theme": { + "name": "classic", + "axis": { + "blank": true + }, + "line": { + "blank": true + }, + "axis_ontop": false, + "axis_ontop_y": false, + "axis_ontop_x": false + } + }, + "apply_color_scheme": true, + "swing_enabled": true + } + }, + "execution_count": 16, + "metadata": {}, + "output_type": "execute_result" + } + ], + "execution_count": 16 + }, + { + "metadata": {}, + "cell_type": "markdown", + "source": [ + "While Processing clearly is the slowest part, the Proteus part is still interesting. Because it affects _all_ message types.\n", + "Processing can be very different between messages and requires an investigation for _each_ message type to find bottlenecks and improvement opportunities.\n", + "\n", + "With that in mind, let's dive a bit deeper into Proteus. Let's split it into smaller chunks and see what we can improve there." + ] + }, + { + "metadata": { + "ExecuteTime": { + "end_time": "2024-09-02T08:30:24.568994Z", + "start_time": "2024-09-02T08:30:23.971615300Z" + } + }, + "cell_type": "code", + "source": [ + "val initialProteusMeasurements = initialData.map { it.proteus }\n", + "val checkingSession by column(initialProteusMeasurements.map { it.checkingSession.inWholeMilliseconds })\n", + "val decrypting by column(initialProteusMeasurements.map { it.decrypting.inWholeMilliseconds })\n", + "val savingSession by column(initialProteusMeasurements.map { it.savingSession.inWholeMilliseconds })\n", + "val eventNumber by column(buildList { repeat(initialProteusMeasurements.size) { i -> add(i + 1)} })\n", + "val detailedFrame = dataFrameOf(eventNumber, checkingSession, decrypting, savingSession)\n", + " .gather(checkingSession, decrypting, savingSession)\n", + " .into(\"measurements\", \"timeSpent\")\n", + "\n", + "detailedFrame.plot {\n", + " layout.title = \"Time taken in each phase of Proteus Unpacking, for different events\"\n", + " points {\n", + " x(\"measurements\")\n", + " y(\"timeSpent\")\n", + " color(\"measurements\")\n", + " position = Position.jitter()\n", + " }\n", + "}\n" + ], + "outputs": [ + { + "data": { + "text/html": [ + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " checkingSession\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " decrypting\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " savingSession\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 0\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 20\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 40\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 60\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 80\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 100\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 120\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Time taken in each phase of Proteus Unpacking, for different events\n", + " \n", + " \n", + " \n", + " \n", + " timeSpent\n", + " \n", + " \n", + " \n", + " \n", + " measurements\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " measurements\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " checkingSession\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " decrypting\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " savingSession\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + "\n", + " " + ], + "application/plot+json": { + "output_type": "lets_plot_spec", + "output": { + "ggtitle": { + "text": "Time taken in each phase of Proteus Unpacking, for different events" + }, + "mapping": {}, + "data": { + "timeSpent": [ + 8.0, + 63.0, + 30.0, + 10.0, + 36.0, + 21.0, + 19.0, + 25.0, + 49.0, + 10.0, + 30.0, + 50.0, + 40.0, + 77.0, + 21.0, + 5.0, + 20.0, + 46.0, + 9.0, + 20.0, + 20.0, + 37.0, + 117.0, + 34.0, + 129.0, + 61.0, + 12.0, + 9.0, + 69.0, + 19.0, + 34.0, + 106.0, + 57.0, + 16.0, + 10.0, + 76.0, + 7.0, + 85.0, + 56.0, + 11.0, + 60.0, + 13.0, + 6.0, + 13.0, + 85.0, + 13.0, + 28.0, + 30.0, + 6.0, + 12.0, + 14.0, + 18.0, + 56.0, + 10.0, + 5.0, + 22.0, + 43.0, + 22.0, + 15.0, + 18.0, + 7.0, + 11.0, + 25.0, + 37.0, + 50.0, + 31.0, + 6.0, + 10.0, + 17.0, + 7.0, + 77.0, + 60.0, + 6.0, + 76.0, + 12.0, + 9.0, + 17.0, + 10.0, + 7.0, + 10.0, + 8.0, + 14.0, + 28.0, + 92.0, + 18.0, + 14.0, + 35.0, + 9.0, + 10.0, + 32.0, + 58.0, + 15.0, + 46.0, + 48.0, + 82.0, + 15.0, + 4.0, + 34.0, + 17.0, + 27.0, + 28.0, + 18.0, + 27.0, + 66.0, + 30.0, + 48.0, + 90.0, + 57.0, + 44.0, + 53.0, + 49.0, + 12.0, + 35.0, + 9.0 + ], + "measurements": [ + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession", + "checkingSession", + "decrypting", + "savingSession" + ] + }, + "kind": "plot", + "scales": [ + { + "aesthetic": "x", + "discrete": true + }, + { + "aesthetic": "y", + "limits": [ + null, + null + ] + }, + { + "aesthetic": "color", + "discrete": true + } + ], + "layers": [ + { + "mapping": { + "x": "measurements", + "y": "timeSpent", + "color": "measurements" + }, + "stat": "identity", + "sampling": "none", + "position": "jitter", + "geom": "point" + } + ] + }, + "apply_color_scheme": true, + "swing_enabled": true + } + }, + "execution_count": 17, + "metadata": {}, + "output_type": "execute_result" + } + ], + "execution_count": 17 + }, + { + "metadata": {}, + "cell_type": "markdown", + "source": [ + "While the colours might cause seizure, it goes to show how random it is. In some times saving session is slow. In some times checking session is slow. In some times decrypting is slow.\n", + "\n", + "One thing can definitely be seen from this, is that decrypting is the slowest part.\n", + "\n", + "Unfortunately, decrypting is something we can't solve on our end. It's embedded within CoreCrypto / CryptoBox, and we are unable to change it.\n", + "\n", + "Here's a simpler visualization:" + ] + }, + { + "metadata": { + "ExecuteTime": { + "end_time": "2024-09-02T08:30:24.856529300Z", + "start_time": "2024-09-02T08:30:24.608176900Z" + } + }, + "cell_type": "code", + "source": [ + "val steps by columnOf(\"Checking Session\", \"Decrypting\", \"Saving Session\")\n", + "val values by columnOf(checkingSession.sum(), decrypting.sum(), savingSession.sum())\n", + "\n", + "val dataFrame = dataFrameOf(steps, values)\n", + "dataFrame.plot {\n", + " pie {\n", + " slice(values)\n", + " fillColor(steps)\n", + " }\n", + " layout {\n", + " title = \"Time share in different Proteus phases\"\n", + " style(Style.Void)\n", + " }\n", + "}" + ], + "outputs": [ + { + "data": { + "text/html": [ + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Time share in different Proteus phases\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " steps\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Checking Session\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Decrypting\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Saving Session\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + "\n", + " " + ], + "application/plot+json": { + "output_type": "lets_plot_spec", + "output": { + "ggtitle": { + "text": "Time share in different Proteus phases" + }, + "mapping": {}, + "data": { + "values": [ + 802.0, + 1631.0, + 1267.0 + ], + "steps": [ + "Checking Session", + "Decrypting", + "Saving Session" + ] + }, + "kind": "plot", + "scales": [ + { + "aesthetic": "fill", + "discrete": true + } + ], + "layers": [ + { + "mapping": { + "slice": "values", + "fill": "steps" + }, + "stat": "identity", + "sampling": "none", + "position": "identity", + "geom": "pie" + } + ], + "theme": { + "name": "classic", + "axis": { + "blank": true + }, + "line": { + "blank": true + }, + "axis_ontop": false, + "axis_ontop_y": false, + "axis_ontop_x": false + } + }, + "apply_color_scheme": true, + "swing_enabled": true + } + }, + "execution_count": 18, + "metadata": {}, + "output_type": "execute_result" + } + ], + "execution_count": 18 + }, + { + "metadata": {}, + "cell_type": "markdown", + "source": [ + "Clearly decrypting is the biggest offender. And as mentioned before, we can't do much about it.\n", + "\n", + "However, we might have quick wins and reduce `Saving Session` and `Checking Session`, which account for almost 50% of the total Proteus time." + ] + }, + { + "metadata": {}, + "cell_type": "markdown", + "source": [ + "## Idea #1\n", + "Remove `Saving Session` completely. It's unnecessary as CoreCrypto will perform session saving in every `decrypt`. We're doing that unnecessarily.\n", + "\n", + "## Idea #2\n", + "Cache existing sessions in-memory. Instead of using IO and relying solely on CoreCrypto to know if sessions exist or not, we can store known sessions in memory.\n", + "If sessions are deleted, we can remove from the memory cache. \n", + "\n", + "## Results\n", + "After doing the first idea, I collected data and stored it in `NotSavingSession.txt`. After that, I also did the second idea and collected data, bringing to the joined improvements." + ] + }, + { + "metadata": { + "ExecuteTime": { + "end_time": "2024-09-02T08:30:25.503196600Z", + "start_time": "2024-09-02T08:30:24.972036600Z" + } + }, + "cell_type": "code", + "source": [ + "val withoutSessionSavingData = getDataFromLogs(\"NotSavingSession.txt\")\n", + "val withSessionCacheData = getDataFromLogs(\"WithExistingSessionCache.txt\")\n", + "\n", + "val initialTime = initialData.map { it.total.inWholeMilliseconds to \"Initial\" }\n", + "val withoutSessionSaving =\n", + " withoutSessionSavingData.map { it.total.inWholeMilliseconds to \"NoSessionSaving\" }\n", + "val withCache = withSessionCacheData.map { it.total.inWholeMilliseconds to \"WithSessionCache\" }\n", + "val allData = (initialTime + withoutSessionSaving + withCache)\n", + "val timeTaken by column(allData.map { it.first })\n", + "val approach by column(allData.map { it.second })\n", + "\n", + "val averages = listOf(initialTime.map { it.first }.average(), withoutSessionSaving.map { it.first }.average(), withCache.map { it.first }.average())\n", + "val dataFrame = dataFrameOf(timeTaken, approach)\n", + "\n", + "dataFrame.plot {\n", + " layout.title = \"Average time taken to fully process events across different approaches\"\n", + " points {\n", + " y(timeTaken)\n", + " x(approach)\n", + " color(approach)\n", + " position = Position.jitter()\n", + " }\n", + " line {\n", + " y(averages) {\n", + " axis.name = \"Time Taken (ms)\"\n", + " }\n", + " x(approach.distinct()) {\n", + " axis.name = \"Approach\"\n", + " }\n", + " color = Color.PURPLE\n", + " this.tooltips(true)\n", + " }\n", + "}" + ], + "outputs": [ + { + "data": { + "text/html": [ + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Initial\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " NoSessionSaving\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " WithSessionCache\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 100\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 200\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 300\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 400\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 500\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Average time taken to fully process events across different approaches\n", + " \n", + " \n", + " \n", + " \n", + " Time Taken (ms)\n", + " \n", + " \n", + " \n", + " \n", + " Approach\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " approach\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Initial\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " NoSessionSaving\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " WithSessionCache\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + "\n", + " " + ], + "application/plot+json": { + "output_type": "lets_plot_spec", + "output": { + "ggtitle": { + "text": "Average time taken to fully process events across different approaches" + }, + "mapping": {}, + "data": { + "timeTaken": [ + 349.0, + 150.0, + 240.0, + 347.0, + 268.0, + 182.0, + 112.0, + 363.0, + 481.0, + 299.0, + 400.0, + 242.0, + 322.0, + 150.0, + 183.0, + 161.0, + 104.0, + 178.0, + 159.0, + 127.0, + 174.0, + 306.0, + 161.0, + 233.0, + 218.0, + 86.0, + 122.0, + 313.0, + 261.0, + 201.0, + 286.0, + 275.0, + 164.0, + 203.0, + 325.0, + 378.0, + 337.0, + 158.0, + 412.0, + 267.0, + 140.0, + 292.0, + 444.0, + 127.0, + 226.0, + 231.0, + 327.0, + 147.0, + 205.0, + 330.0, + 286.0, + 314.0, + 172.0, + 198.0, + 360.0, + 124.0, + 232.0, + 151.0, + 181.0, + 112.0, + 162.0, + 80.0, + 72.0, + 68.0, + 122.0, + 191.0, + 89.0, + 104.0, + 177.0, + 72.0, + 72.0, + 109.0, + 240.0, + 117.0, + 373.0, + 201.0, + 106.0, + 65.0, + 128.0, + 191.0, + 147.0, + 143.0, + 112.0, + 133.0, + 168.0, + 251.0, + 180.0, + 343.0, + 200.0, + 171.0, + 164.0, + 104.0, + 102.0, + 77.0, + 103.0, + 191.0, + 129.0, + 204.0, + 117.0, + 73.0, + 198.0, + 165.0, + 190.0, + 78.0, + 172.0, + 124.0, + 172.0, + 155.0, + 74.0, + 54.0, + 259.0, + 103.0, + 89.0, + 168.0, + 58.0, + 135.0, + 92.0, + 136.0, + 97.0, + 145.0, + 145.0, + 151.0, + 263.0, + 204.0, + 160.0, + 221.0, + 116.0, + 92.0, + 138.0 + ], + "approach": [ + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "Initial", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "NoSessionSaving", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache", + "WithSessionCache" + ] + }, + "kind": "plot", + "scales": [ + { + "aesthetic": "y", + "limits": [ + null, + null + ] + }, + { + "aesthetic": "x", + "discrete": true + }, + { + "aesthetic": "color", + "discrete": true + }, + { + "aesthetic": "y", + "name": "Time Taken (ms)", + "limits": [ + null, + null + ] + }, + { + "aesthetic": "x", + "discrete": true, + "name": "Approach" + } + ], + "layers": [ + { + "mapping": { + "y": "timeTaken", + "x": "approach", + "color": "approach" + }, + "stat": "identity", + "sampling": "none", + "position": "jitter", + "geom": "point" + }, + { + "mapping": { + "y": "y", + "x": "approach" + }, + "stat": "identity", + "data": { + "y": [ + 237.31578947368422, + 195.71794871794873, + 147.1153846153846 + ], + "approach": [ + "Initial", + "NoSessionSaving", + "WithSessionCache" + ] + }, + "color": "#9a60b4", + "sampling": "none", + "position": "identity", + "geom": "line", + "tooltips": {} + } + ] + }, + "apply_color_scheme": true, + "swing_enabled": true + } + }, + "execution_count": 19, + "metadata": {}, + "output_type": "execute_result" + } + ], + "execution_count": 19 + }, + { + "metadata": {}, + "cell_type": "markdown", + "source": [ + "## First win\n", + "Clearly we're up to something. Processing events is clearly faster with the changes in Proteus. The average time went from 247ms, to 196ms without saving session, and then down to 147ms without saving session + caching existing sessions.\n", + "\n", + "## But we're not over yet\n", + "Maybe we can also analyse the different parts of `ProcessingMessage` and identify what is taking more time? For that, we can join all the logs taken so far and ignore the Proteus part." + ] + }, + { + "metadata": { + "ExecuteTime": { + "end_time": "2024-09-02T08:30:25.811756500Z", + "start_time": "2024-09-02T08:30:25.533313800Z" + } + }, + "cell_type": "code", + "source": [ + "val allMeasurements = initialData + withoutSessionSavingData + withSessionCacheData\n", + "val allMessageProcessing = allMeasurements.map { \n", + " it.processingMessage\n", + "}\n", + "val checkingLegalhold by column(allMessageProcessing.map { it.checkingLegalhold.inWholeMilliseconds })\n", + "val handlingContent by column(allMessageProcessing.map { it.handlingMessageContent.inWholeMilliseconds })\n", + "val postHandling by column(allMessageProcessing.map { it.postHandling.inWholeMilliseconds })\n", + "val eventNumber by column(buildList { repeat(allMessageProcessing.size) { i -> add(i + 1)} })\n", + "val detailedFrame = dataFrameOf(eventNumber, checkingLegalhold, handlingContent, postHandling)\n", + " .gather(checkingLegalhold, handlingContent, postHandling)\n", + " .into(\"measurements\", \"timeSpent\")\n", + "\n", + "detailedFrame.plot { \n", + " points { \n", + " x(\"measurements\")\n", + " y(\"timeSpent\")\n", + " position = Position.jitter()\n", + " color(\"measurements\")\n", + " }\n", + "}\n" + ], + "outputs": [ + { + "data": { + "text/html": [ + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " checkingLegalhold\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " handlingContent\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " postHandling\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 0\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 50\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 100\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 150\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 200\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 250\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 300\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " 350\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " timeSpent\n", + " \n", + " \n", + " \n", + " \n", + " measurements\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " measurements\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " checkingLegalhold\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " handlingContent\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " postHandling\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + "\n", + " " + ], + "application/plot+json": { + "output_type": "lets_plot_spec", + "output": { + "mapping": {}, + "data": { + "timeSpent": [ + 5.0, + 130.0, + 0.0, + 23.0, + 52.0, + 0.0, + 12.0, + 100.0, + 0.0, + 86.0, + 141.0, + 0.0, + 9.0, + 106.0, + 0.0, + 3.0, + 99.0, + 0.0, + 4.0, + 41.0, + 0.0, + 11.0, + 142.0, + 0.0, + 131.0, + 124.0, + 0.0, + 12.0, + 144.0, + 8.0, + 6.0, + 179.0, + 0.0, + 17.0, + 106.0, + 0.0, + 19.0, + 112.0, + 0.0, + 8.0, + 50.0, + 0.0, + 21.0, + 52.0, + 0.0, + 4.0, + 62.0, + 0.0, + 5.0, + 40.0, + 0.0, + 5.0, + 79.0, + 0.0, + 3.0, + 78.0, + 0.0, + 4.0, + 49.0, + 0.0, + 4.0, + 119.0, + 0.0, + 18.0, + 139.0, + 0.0, + 12.0, + 84.0, + 0.0, + 26.0, + 55.0, + 0.0, + 7.0, + 104.0, + 0.0, + 5.0, + 30.0, + 0.0, + 3.0, + 87.0, + 0.0, + 4.0, + 106.0, + 0.0, + 28.0, + 144.0, + 0.0, + 4.0, + 105.0, + 0.0, + 39.0, + 101.0, + 0.0, + 6.0, + 72.0, + 0.0, + 14.0, + 86.0, + 0.0, + 24.0, + 92.0, + 0.0, + 3.0, + 191.0, + 0.0, + 13.0, + 161.0, + 0.0, + 33.0, + 122.0, + 0.0, + 16.0, + 79.0, + 0.0, + 0.0, + 97.0, + 0.0, + 10.0, + 181.0, + 0.0, + 9.0, + 75.0, + 0.0, + 5.0, + 138.0, + 0.0, + 4.0, + 346.0, + 0.0, + 14.0, + 43.0, + 0.0, + 5.0, + 104.0, + 0.0, + 33.0, + 58.0, + 0.0, + 4.0, + 89.0, + 0.0, + 9.0, + 87.0, + 0.0, + 4.0, + 82.0, + 0.0, + 10.0, + 139.0, + 0.0, + 6.0, + 125.0, + 0.0, + 28.0, + 121.0, + 0.0, + 9.0, + 101.0, + 0.0, + 4.0, + 111.0, + 0.0, + 5.0, + 210.0, + 0.0, + 7.0, + 26.0, + 0.0, + 43.0, + 84.0, + 0.0, + 5.0, + 65.0, + 0.0, + 6.0, + 57.0, + 0.0, + 5.0, + 37.0, + 0.0, + 4.0, + 61.0, + 0.0, + 4.0, + 20.0, + 0.0, + 9.0, + 16.0, + 0.0, + 6.0, + 14.0, + 0.0, + 10.0, + 25.0, + 0.0, + 7.0, + 45.0, + 0.0, + 4.0, + 29.0, + 0.0, + 4.0, + 16.0, + 0.0, + 40.0, + 24.0, + 0.0, + 6.0, + 21.0, + 0.0, + 19.0, + 11.0, + 0.0, + 4.0, + 58.0, + 0.0, + 4.0, + 120.0, + 0.0, + 4.0, + 52.0, + 0.0, + 79.0, + 47.0, + 0.0, + 10.0, + 106.0, + 0.0, + 25.0, + 16.0, + 0.0, + 0.0, + 30.0, + 0.0, + 8.0, + 87.0, + 0.0, + 43.0, + 84.0, + 0.0, + 22.0, + 82.0, + 0.0, + 18.0, + 39.0, + 0.0, + 12.0, + 59.0, + 0.0, + 4.0, + 43.0, + 0.0, + 4.0, + 74.0, + 0.0, + 17.0, + 160.0, + 0.0, + 29.0, + 32.0, + 0.0, + 8.0, + 110.0, + 0.0, + 26.0, + 100.0, + 0.0, + 32.0, + 77.0, + 0.0, + 13.0, + 59.0, + 0.0, + 22.0, + 54.0, + 0.0, + 7.0, + 56.0, + 0.0, + 4.0, + 30.0, + 0.0, + 13.0, + 23.0, + 0.0, + 5.0, + 63.0, + 0.0, + 7.0, + 45.0, + 0.0, + 4.0, + 82.0, + 0.0, + 5.0, + 41.0, + 0.0, + 5.0, + 23.0, + 0.0, + 5.0, + 84.0, + 0.0, + 6.0, + 44.0, + 0.0, + 23.0, + 73.0, + 0.0, + 15.0, + 19.0, + 0.0, + 7.0, + 95.0, + 0.0, + 30.0, + 31.0, + 0.0, + 19.0, + 70.0, + 0.0, + 9.0, + 19.0, + 0.0, + 4.0, + 18.0, + 0.0, + 4.0, + 30.0, + 0.0, + 13.0, + 114.0, + 0.0, + 28.0, + 16.0, + 0.0, + 4.0, + 14.0, + 0.0, + 36.0, + 41.0, + 0.0, + 5.0, + 32.0, + 0.0, + 4.0, + 38.0, + 0.0, + 4.0, + 47.0, + 0.0, + 4.0, + 26.0, + 0.0, + 14.0, + 46.0, + 3.0, + 5.0, + 76.0, + 0.0, + 19.0, + 76.0, + 0.0, + 5.0, + 56.0, + 0.0, + 11.0, + 99.0, + 0.0, + 13.0, + 78.0, + 0.0, + 31.0, + 24.0, + 0.0, + 50.0, + 69.0, + 0.0, + 5.0, + 11.0, + 0.0, + 9.0, + 45.0, + 0.0, + 6.0, + 83.0, + 0.0 + ], + "measurements": [ + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling", + "checkingLegalhold", + "handlingContent", + "postHandling" + ] + }, + "kind": "plot", + "scales": [ + { + "aesthetic": "x", + "discrete": true + }, + { + "aesthetic": "y", + "limits": [ + null, + null + ] + }, + { + "aesthetic": "color", + "discrete": true + } + ], + "layers": [ + { + "mapping": { + "x": "measurements", + "y": "timeSpent", + "color": "measurements" + }, + "stat": "identity", + "sampling": "none", + "position": "jitter", + "geom": "point" + } + ] + }, + "apply_color_scheme": true, + "swing_enabled": true + } + }, + "execution_count": 20, + "metadata": {}, + "output_type": "execute_result" + } + ], + "execution_count": 20 + }, + { + "metadata": {}, + "cell_type": "markdown", + "source": [ + "## Bad news\n", + "\n", + "While checking legalhold is definitely a bit more random (probably due to IO operations), handling each different content is definitely the biggest offender.\n", + "Here's a comparison across all different steps using the most improved data." + ] + }, + { + "metadata": { + "ExecuteTime": { + "end_time": "2024-09-02T08:30:26.254403300Z", + "start_time": "2024-09-02T08:30:25.873610800Z" + } + }, + "cell_type": "code", + "source": [ + "import org.jetbrains.kotlinx.kandy.ir.feature.FeatureName\n", + "\n", + "val pairs =\n", + " withSessionCacheData.map { it.proteus.checkingSession.inWholeMicroseconds to \"Checking Session\" } +\n", + " withSessionCacheData.map { it.proteus.decrypting.inWholeMicroseconds to \"Decrypting\" } +\n", + " withSessionCacheData.map { it.proteus.savingSession.inWholeMicroseconds to \"Saving Session\" } +\n", + " withSessionCacheData.map { it.processingMessage.checkingLegalhold.inWholeMicroseconds to \"Checking Legalhold\" } +\n", + " withSessionCacheData.map { it.processingMessage.handlingMessageContent.inWholeMicroseconds to \"Handling Content\" } +\n", + " withSessionCacheData.map { it.processingMessage.postHandling.inWholeMicroseconds to \"Post Handling\" } +\n", + " withSessionCacheData.map { it.unknownTime.inWholeMicroseconds to \"Other\" }\n", + "\n", + "val value by column(pairs.map { it.first })\n", + "val stepName by column(pairs.map { it.second })\n", + "val dataSet = dataFrameOf(value, stepName)\n", + "dataSet.groupBy(stepName).aggregate {\n", + " sum(value) into \"total\"\n", + "}.plot {\n", + " pie {\n", + " slice(\"total\")\n", + " fillColor(\"stepName\")\n", + " }\n", + " layout {\n", + " title = \"Time spent unpacking and processing message events after improvements\"\n", + " style(Style.Void)\n", + " }\n", + "}" + ], + "outputs": [ + { + "data": { + "text/html": [ + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Time spent unpacking and processing message events after improvements\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " stepName\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Checking Session\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Decrypting\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Saving Session\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Checking Legalhold\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Handling Content\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Post Handling\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " Other\n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + " \n", + "\n", + " " + ], + "application/plot+json": { + "output_type": "lets_plot_spec", + "output": { + "ggtitle": { + "text": "Time spent unpacking and processing message events after improvements" + }, + "mapping": {}, + "data": { + "total": [ + 6634.0, + 2872468.0, + 232.0, + 721930.0, + 2952363.0, + 6072.0, + 1090122.0 + ], + "stepName": [ + "Checking Session", + "Decrypting", + "Saving Session", + "Checking Legalhold", + "Handling Content", + "Post Handling", + "Other" + ] + }, + "kind": "plot", + "scales": [ + { + "aesthetic": "fill", + "discrete": true + } + ], + "layers": [ + { + "mapping": { + "slice": "total", + "fill": "stepName" + }, + "stat": "identity", + "sampling": "none", + "position": "identity", + "geom": "pie" + } + ], + "theme": { + "name": "classic", + "axis": { + "blank": true + }, + "line": { + "blank": true + }, + "axis_ontop": false, + "axis_ontop_y": false, + "axis_ontop_x": false + } + }, + "apply_color_scheme": true, + "swing_enabled": true + } + }, + "execution_count": 21, + "metadata": {}, + "output_type": "execute_result" + } + ], + "execution_count": 21 + }, + { + "metadata": {}, + "cell_type": "markdown", + "source": [ + "## What's next?\n", + "\n", + "### CoreCrypto transactions\n", + "CoreCrypto has plans to create a transaction API so we can batch-decrypt messages, which should speed up the `decrypting` part.\n", + "\n", + "### Check \"Other\" slice\n", + "Perhaps there is still a bit of time to gain in the \"Other\" part of the code, which is related to Protobuf parsing, Base64 decoding, etc. ?\n", + "\n", + "### Dive deeper into each message type\n", + "Keep in mind that most of the events collected for the experiments above were Text events. Which seems to be one of the worst performing messages we process.\n", + "This is definitely the most demanding job, as it requires pretty much one investigation for Text, one for LastRead, one for Asset, one for Receipt, etc.\n", + "But might be one of the most fruitful ones, and strikes a good balance between a major refactor that would be with CoreCrypto transactions, and small / segmented improvements across the processing pipeline." + ] + } + ], + "metadata": { + "kernelspec": { + "display_name": "Kotlin", + "language": "kotlin", + "name": "kotlin" + }, + "language_info": { + "name": "kotlin", + "version": "1.9.23", + "mimetype": "text/x-kotlin", + "file_extension": ".kt", + "pygments_lexer": "kotlin", + "codemirror_mode": "text/x-kotlin", + "nbconvert_exporter": "" + }, + "ktnbPluginMetadata": { + "projectLibraries": [] + } + }, + "nbformat": 4, + "nbformat_minor": 0 +} diff --git a/docs/notebooks/event-performance-investigation/logs/InitialData.txt b/docs/notebooks/event-performance-investigation/logs/InitialData.txt new file mode 100644 index 00000000000..bf35441bacd --- /dev/null +++ b/docs/notebooks/event-performance-investigation/logs/InitialData.txt @@ -0,0 +1,152 @@ + +Decrypting Proteus. CheckingSession: 8.873250ms; Decrypting: 63.703776ms; Saving Session: 30.135295ms +Processing Application Message. LegalHold: 5.755086ms; Actually Handling: 130.706096ms; Post Handling: 143.717us +349 Text + +Decrypting Proteus. CheckingSession: 10.304281ms; Decrypting: 36.299642ms; Saving Session: 21.362386ms +Processing Application Message. LegalHold: 23.325888ms; Actually Handling: 52.317098ms; Post Handling: 47.323us +150 Text + +Decrypting Proteus. CheckingSession: 19.705038ms; Decrypting: 25.850708ms; Saving Session: 49.176188ms +Processing Application Message. LegalHold: 12.177897ms; Actually Handling: 100.877320ms; Post Handling: 58.146us +240 Text + +Decrypting Proteus. CheckingSession: 10.535889ms; Decrypting: 30.623861ms; Saving Session: 50.635539ms +Processing Application Message. LegalHold: 86.545207ms; Actually Handling: 141.545858ms; Post Handling: 212.321us +347 Text + +Decrypting Proteus. CheckingSession: 40.843750ms; Decrypting: 77.642823ms; Saving Session: 21.599772ms +Processing Application Message. LegalHold: 9.775106ms; Actually Handling: 106.065226ms; Post Handling: 45.207us +268 Text + +Decrypting Proteus. CheckingSession: 5.257365ms; Decrypting: 20.301676ms; Saving Session: 46.290242ms +Processing Application Message. LegalHold: 3.956584ms; Actually Handling: 99.363404ms; Post Handling: 55.868us +182 Text + +Decrypting Proteus. CheckingSession: 9.790934ms; Decrypting: 20.166585ms; Saving Session: 20.536784ms +Processing Application Message. LegalHold: 4.910481ms; Actually Handling: 41.863892ms; Post Handling: 43.742us +112 Text + +Decrypting Proteus. CheckingSession: 37.533936ms; Decrypting: 117.194052ms; Saving Session: 34.765462ms +Processing Application Message. LegalHold: 11.211955ms; Actually Handling: 142.946085ms; Post Handling: 62.215us +363 Text + +Decrypting Proteus. CheckingSession: 129.018718ms; Decrypting: 61.166015ms; Saving Session: 12.040650ms +Processing Application Message. LegalHold: 131.752482ms; Actually Handling: 124.796590ms; Post Handling: 46.672us +481 Text + +Decrypting Proteus. CheckingSession: 9.000204ms; Decrypting: 69.963949ms; Saving Session: 19.456218ms +Processing Application Message. LegalHold: 12.183798ms; Actually Handling: 144.756022ms; Post Handling: 8.200154ms +299 Text + +Decrypting Proteus. CheckingSession: 34.256022ms; Decrypting: 106.964966ms; Saving Session: 57.150595ms +Processing Application Message. LegalHold: 6.519572ms; Actually Handling: 179.368612ms; Post Handling: 44.678us +400 Text + +Decrypting Proteus. CheckingSession: 16.447510ms; Decrypting: 10.732666ms; Saving Session: 76.608684ms +Processing Application Message. LegalHold: 17.636882ms; Actually Handling: 106.291829ms; Post Handling: 42.358us +242 Text + +Decrypting Proteus. CheckingSession: 7.767496ms; Decrypting: 85.712199ms; Saving Session: 56.541259ms +Processing Application Message. LegalHold: 19.073527ms; Actually Handling: 112.489461ms; Post Handling: 45.288us +322 Text + +Decrypting Proteus. CheckingSession: 11.468709ms; Decrypting: 60.700643ms; Saving Session: 13.350546ms +Processing Application Message. LegalHold: 8.505982ms; Actually Handling: 50.083130ms; Post Handling: 45.532us +150 Text + +Decrypting Proteus. CheckingSession: 6.188883ms; Decrypting: 13.053426ms; Saving Session: 85.124837ms +Processing Application Message. LegalHold: 21.323039ms; Actually Handling: 52.064534ms; Post Handling: 44.271us +183 Text + +Decrypting Proteus. CheckingSession: 13.070516ms; Decrypting: 28.716634ms; Saving Session: 30.298055ms +Processing Application Message. LegalHold: 4.070516ms; Actually Handling: 62.070149ms; Post Handling: 46.346us +161 Text + +Decrypting Proteus. CheckingSession: 6.138061ms; Decrypting: 12.006470ms; Saving Session: 14.416707ms +Processing Application Message. LegalHold: 5.838745ms; Actually Handling: 40.329020ms; Post Handling: 45.084us +104 Text + +Decrypting Proteus. CheckingSession: 18.136312ms; Decrypting: 56.142212ms; Saving Session: 10.411458ms +Processing Application Message. LegalHold: 5.751913ms; Actually Handling: 79.311198ms; Post Handling: 86.67us +178 Text + +Decrypting Proteus. CheckingSession: 5.159220ms; Decrypting: 22.406942ms; Saving Session: 43.825399ms +Processing Application Message. LegalHold: 3.482463ms; Actually Handling: 78.667847ms; Post Handling: 46.102us +159 Text + +Decrypting Proteus. CheckingSession: 22.073405ms; Decrypting: 15.910563ms; Saving Session: 18.681885ms +Processing Application Message. LegalHold: 4.313762ms; Actually Handling: 49.198934ms; Post Handling: 42.603us +127 Text + +Decrypting Proteus. CheckingSession: 7.837036ms; Decrypting: 11.566772ms; Saving Session: 25.379231ms +Processing Application Message. LegalHold: 4.045329ms; Actually Handling: 119.658447ms; Post Handling: 45.573us +174 Text + +Decrypting Proteus. CheckingSession: 37.247396ms; Decrypting: 50.347819ms; Saving Session: 31.310221ms +Processing Application Message. LegalHold: 18.579997ms; Actually Handling: 139.728719ms; Post Handling: 90.698us +306 Text + +Decrypting Proteus. CheckingSession: 6.503500ms; Decrypting: 10.227702ms; Saving Session: 17.202026ms +Processing Application Message. LegalHold: 12.241333ms; Actually Handling: 84.598836ms; Post Handling: 43.294us +161 Text + +Decrypting Proteus. CheckingSession: 7.555704ms; Decrypting: 77.212647ms; Saving Session: 60.606690ms +Processing Application Message. LegalHold: 26.573812ms; Actually Handling: 55.140462ms; Post Handling: 57.862us +233 Text + +Decrypting Proteus. CheckingSession: 6.635539ms; Decrypting: 76.914876ms; Saving Session: 12.664348ms +Processing Application Message. LegalHold: 7.748047ms; Actually Handling: 104.782104ms; Post Handling: 45.044us +218 Text + +Decrypting Proteus. CheckingSession: 9.785726ms; Decrypting: 17.814534ms; Saving Session: 10.872436ms +Processing Application Message. LegalHold: 5.510823ms; Actually Handling: 30.021362ms; Post Handling: 46.021us +86 Text + +Decrypting Proteus. CheckingSession: 7.540120ms; Decrypting: 10.186483ms; Saving Session: 8.016560ms +Processing Application Message. LegalHold: 3.805827ms; Actually Handling: 87.553345ms; Post Handling: 45.899us +122 Text + +Decrypting Proteus. CheckingSession: 14.270101ms; Decrypting: 28.638753ms; Saving Session: 92.611044ms +Processing Application Message. LegalHold: 4.849487ms; Actually Handling: 106.860189ms; Post Handling: 61.442us +313 Text + +Decrypting Proteus. CheckingSession: 18.783529ms; Decrypting: 14.807129ms; Saving Session: 35.545858ms +Processing Application Message. LegalHold: 28.228353ms; Actually Handling: 144.122518ms; Post Handling: 44.719us +261 Text + +Decrypting Proteus. CheckingSession: 9.662638ms; Decrypting: 10.893880ms; Saving Session: 32.210978ms +Processing Application Message. LegalHold: 4.977783ms; Actually Handling: 105.997029ms; Post Handling: 45.451us +201 Text + +Decrypting Proteus. CheckingSession: 58.855998ms; Decrypting: 15.815918ms; Saving Session: 46.989014ms +Processing Application Message. LegalHold: 39.791626ms; Actually Handling: 101.596924ms; Post Handling: 45.573us +286 Text + +Decrypting Proteus. CheckingSession: 48.868653ms; Decrypting: 82.024048ms; Saving Session: 15.148235ms +Processing Application Message. LegalHold: 6.876343ms; Actually Handling: 72.648153ms; Post Handling: 44.027us +275 Text + +Decrypting Proteus. CheckingSession: 4.992024ms; Decrypting: 34.686604ms; Saving Session: 17.456991ms +Processing Application Message. LegalHold: 14.882975ms; Actually Handling: 86.396240ms; Post Handling: 47.282us +164 Text + +Decrypting Proteus. CheckingSession: 27.943970ms; Decrypting: 28.186035ms; Saving Session: 18.758708ms +Processing Application Message. LegalHold: 24.808106ms; Actually Handling: 92.472941ms; Post Handling: 69.824us +203 Text + +Decrypting Proteus. CheckingSession: 27.895060ms; Decrypting: 66.050049ms; Saving Session: 30.500814ms +Processing Application Message. LegalHold: 3.519571ms; Actually Handling: 191.166545ms; Post Handling: 47.893us +325 Text + +Decrypting Proteus. CheckingSession: 48.456991ms; Decrypting: 90.494141ms; Saving Session: 57.134359ms +Processing Application Message. LegalHold: 13.465983ms; Actually Handling: 161.665446ms; Post Handling: 41.748us +378 Text + +Decrypting Proteus. CheckingSession: 44.470988ms; Decrypting: 53.007121ms; Saving Session: 49.168823ms +Processing Application Message. LegalHold: 33.682983ms; Actually Handling: 122.440349ms; Post Handling: 43.538us +337 Text + +Decrypting Proteus. CheckingSession: 12.033041ms; Decrypting: 35.181274ms; Saving Session: 9.400960ms +Processing Application Message. LegalHold: 16.091227ms; Actually Handling: 79.925822ms; Post Handling: 44.108us +158 Text diff --git a/docs/notebooks/event-performance-investigation/logs/NotSavingSession.txt b/docs/notebooks/event-performance-investigation/logs/NotSavingSession.txt new file mode 100644 index 00000000000..55f2a282b2d --- /dev/null +++ b/docs/notebooks/event-performance-investigation/logs/NotSavingSession.txt @@ -0,0 +1,156 @@ + +Decrypting Proteus. CheckingSession: 15.454061ms; Decrypting: 28.070231ms; Saving Session: 5.697us +Processing Application Message. LegalHold: 14.933us; Actually Handling: 97.785929ms; Post Handling: 182.657us +412 LastRead + +Decrypting Proteus. CheckingSession: 11.785157ms; Decrypting: 22.148885ms; Saving Session: 4.069us +Processing Application Message. LegalHold: 10.174601ms; Actually Handling: 181.047770ms; Post Handling: 108.154us +267 Text + +Decrypting Proteus. CheckingSession: 17.730428ms; Decrypting: 16.207683ms; Saving Session: 4.761us +Processing Application Message. LegalHold: 9.501302ms; Actually Handling: 75.200358ms; Post Handling: 108.805us +140 Text + +Decrypting Proteus. CheckingSession: 95.788696ms; Decrypting: 36.985514ms; Saving Session: 5.045us +Processing Application Message. LegalHold: 5.578369ms; Actually Handling: 138.195842ms; Post Handling: 89.518us +292 Text + +Decrypting Proteus. CheckingSession: 29.748698ms; Decrypting: 45.943482ms; Saving Session: 3.866us +Processing Application Message. LegalHold: 4.784953ms; Actually Handling: 346.692790ms; Post Handling: 89.518us +444 Text + +Decrypting Proteus. CheckingSession: 8.107707ms; Decrypting: 21.656494ms; Saving Session: 3.825us +Processing Application Message. LegalHold: 14.723348ms; Actually Handling: 43.679484ms; Post Handling: 90.698us +127 Text + +Decrypting Proteus. CheckingSession: 42.428589ms; Decrypting: 50.376099ms; Saving Session: 3.988us +Processing Application Message. LegalHold: 5.829631ms; Actually Handling: 104.662761ms; Post Handling: 92.082us +226 Text + +Decrypting Proteus. CheckingSession: 17.885702ms; Decrypting: 108.601074ms; Saving Session: 4.965us +Processing Application Message. LegalHold: 33.264404ms; Actually Handling: 58.645386ms; Post Handling: 91.39us +231 Text + +Decrypting Proteus. CheckingSession: 85.114421ms; Decrypting: 105.152222ms; Saving Session: 5.127us +Processing Application Message. LegalHold: 4.807495ms; Actually Handling: 89.738851ms; Post Handling: 86.548us +327 Text + +Decrypting Proteus. CheckingSession: 15.756429ms; Decrypting: 27.951905ms; Saving Session: 3.906us +Processing Application Message. LegalHold: 9.168823ms; Actually Handling: 87.466471ms; Post Handling: 93.14us +147 Text + +Decrypting Proteus. CheckingSession: 44.635172ms; Decrypting: 60.306600ms; Saving Session: 4.761us +Processing Application Message. LegalHold: 4.242594ms; Actually Handling: 82.865194ms; Post Handling: 95.621us +205 Text + +Decrypting Proteus. CheckingSession: 58.932658ms; Decrypting: 92.710083ms; Saving Session: 5.209us +Processing Application Message. LegalHold: 10.136637ms; Actually Handling: 139.580038ms; Post Handling: 89.274us +330 Text + +Decrypting Proteus. CheckingSession: 33.654093ms; Decrypting: 106.929199ms; Saving Session: 4.964us +Processing Application Message. LegalHold: 6.297811ms; Actually Handling: 125.664958ms; Post Handling: 106.893us +286 Text + +Decrypting Proteus. CheckingSession: 37.078735ms; Decrypting: 110.817546ms; Saving Session: 5.005us +Processing Application Message. LegalHold: 28.246907ms; Actually Handling: 121.051514ms; Post Handling: 87.687us +314 Text + +Decrypting Proteus. CheckingSession: 7.747396ms; Decrypting: 45.533691ms; Saving Session: 5.818us +Processing Application Message. LegalHold: 9.863688ms; Actually Handling: 101.962199ms; Post Handling: 90.902us +172 Text + +Decrypting Proteus. CheckingSession: 8.374227ms; Decrypting: 59.100220ms; Saving Session: 3.866us +Processing Application Message. LegalHold: 4.148681ms; Actually Handling: 111.556722ms; Post Handling: 89.559us +198 Text + +Decrypting Proteus. CheckingSession: 61.912313ms; Decrypting: 69.451416ms; Saving Session: 4.965us +Processing Application Message. LegalHold: 5.938232ms; Actually Handling: 210.333130ms; Post Handling: 138.346us +360 Text + +Decrypting Proteus. CheckingSession: 15.601196ms; Decrypting: 10.290812ms; Saving Session: 3.744us +Processing Application Message. LegalHold: 7.292155ms; Actually Handling: 26.934814ms; Post Handling: 43.091us +124 Text + +Decrypting Proteus. CheckingSession: 48.981486ms; Decrypting: 13.180949ms; Saving Session: 3.744us +Processing Application Message. LegalHold: 43.387492ms; Actually Handling: 84.452922ms; Post Handling: 41.789us +232 Text + +Decrypting Proteus. CheckingSession: 10.598593ms; Decrypting: 39.504395ms; Saving Session: 4.232us +Processing Application Message. LegalHold: 5.250448ms; Actually Handling: 65.109619ms; Post Handling: 53.996us +151 Text + +Decrypting Proteus. CheckingSession: 21.209838ms; Decrypting: 62.311402ms; Saving Session: 5.209us +Processing Application Message. LegalHold: 6.484538ms; Actually Handling: 57.000326ms; Post Handling: 39.632us +181 Text + +Decrypting Proteus. CheckingSession: 6.562581ms; Decrypting: 55.756226ms; Saving Session: 5.127us +Processing Application Message. LegalHold: 5.546671ms; Actually Handling: 37.751709ms; Post Handling: 40.405us +112 Text + +Decrypting Proteus. CheckingSession: 40.094686ms; Decrypting: 24.501017ms; Saving Session: 3.906us +Processing Application Message. LegalHold: 4.171590ms; Actually Handling: 61.336955ms; Post Handling: 44.149us +162 Text + +Decrypting Proteus. CheckingSession: 21.579956ms; Decrypting: 26.329590ms; Saving Session: 4.191us +Processing Application Message. LegalHold: 4.704508ms; Actually Handling: 20.097859ms; Post Handling: 41.381us +80 Text + +Decrypting Proteus. CheckingSession: 6.706909ms; Decrypting: 22.204875ms; Saving Session: 5.818us +Processing Application Message. LegalHold: 9.896729ms; Actually Handling: 16.063802ms; Post Handling: 41.423us +72 Text + +Decrypting Proteus. CheckingSession: 15.992961ms; Decrypting: 23.335937ms; Saving Session: 4.883us +Processing Application Message. LegalHold: 6.042847ms; Actually Handling: 14.047811ms; Post Handling: 40.608us +68 Text + +Decrypting Proteus. CheckingSession: 33.254761ms; Decrypting: 33.165324ms; Saving Session: 4.151us +Processing Application Message. LegalHold: 10.563924ms; Actually Handling: 25.756714ms; Post Handling: 46.956us +122 Text + +Decrypting Proteus. CheckingSession: 40.167928ms; Decrypting: 55.158122ms; Saving Session: 4.191us +Processing Application Message. LegalHold: 7.033366ms; Actually Handling: 45.535278ms; Post Handling: 40.975us +191 Text + +Decrypting Proteus. CheckingSession: 20.063924ms; Decrypting: 28.767172ms; Saving Session: 4.069us +Processing Application Message. LegalHold: 4.934366ms; Actually Handling: 29.515666ms; Post Handling: 40.731us +89 Text + +Decrypting Proteus. CheckingSession: 15.520548ms; Decrypting: 57.723185ms; Saving Session: 5.046us +Processing Application Message. LegalHold: 4.028361ms; Actually Handling: 16.930623ms; Post Handling: 42.196us +104 Text + +Decrypting Proteus. CheckingSession: 6.614787ms; Decrypting: 99.018148ms; Saving Session: 5.005us +Processing Application Message. LegalHold: 40.461263ms; Actually Handling: 24.233317ms; Post Handling: 41.341us +177 Text + +Decrypting Proteus. CheckingSession: 19.239502ms; Decrypting: 19.057088ms; Saving Session: 3.907us +Processing Application Message. LegalHold: 6.788941ms; Actually Handling: 21.477051ms; Post Handling: 44.759us +72 Text + +Decrypting Proteus. CheckingSession: 20.884278ms; Decrypting: 13.739380ms; Saving Session: 4.761us +Processing Application Message. LegalHold: 19.949260ms; Actually Handling: 11.556518ms; Post Handling: 37.191us +72 Text + +Decrypting Proteus. CheckingSession: 22.686971ms; Decrypting: 12.227987ms; Saving Session: 4.68us +Processing Application Message. LegalHold: 4.054525ms; Actually Handling: 58.352865ms; Post Handling: 40.446us +109 Text + +Decrypting Proteus. CheckingSession: 33.300741ms; Decrypting: 69.654378ms; Saving Session: 4.964us +Processing Application Message. LegalHold: 4.356689ms; Actually Handling: 120.923299ms; Post Handling: 47.363us +240 Text + +Decrypting Proteus. CheckingSession: 33.834310ms; Decrypting: 18.699748ms; Saving Session: 5.452us +Processing Application Message. LegalHold: 4.842203ms; Actually Handling: 52.177408ms; Post Handling: 54.932us +117 Text + +Decrypting Proteus. CheckingSession: 40.743897ms; Decrypting: 188.739014ms; Saving Session: 6.958us +Processing Application Message. LegalHold: 79.312296ms; Actually Handling: 47.106241ms; Post Handling: 42.48us +373 Text + +Decrypting Proteus. CheckingSession: 52.185547ms; Decrypting: 21.590617ms; Saving Session: 5.005us +Processing Application Message. LegalHold: 10.031861ms; Actually Handling: 106.708211ms; Post Handling: 47.729us +201 Text + +Decrypting Proteus. CheckingSession: 12.232300ms; Decrypting: 43.849935ms; Saving Session: 4.923us +Processing Application Message. LegalHold: 25.414754ms; Actually Handling: 16.168091ms; Post Handling: 41.748us +106 Text diff --git a/docs/notebooks/event-performance-investigation/logs/WithExistingSessionCache.txt b/docs/notebooks/event-performance-investigation/logs/WithExistingSessionCache.txt new file mode 100644 index 00000000000..f396d1b8a7b --- /dev/null +++ b/docs/notebooks/event-performance-investigation/logs/WithExistingSessionCache.txt @@ -0,0 +1,208 @@ + +Decrypting Proteus. CheckingSession: 171.63us; Decrypting: 23.412150ms; Saving Session: 4.72us +Processing Application Message. LegalHold: 17.415us; Actually Handling: 30.606893ms; Post Handling: 61.157us +65 LastRead + +Decrypting Proteus. CheckingSession: 130.615us; Decrypting: 23.862264ms; Saving Session: 4.761us +Processing Application Message. LegalHold: 8.499105ms; Actually Handling: 87.421549ms; Post Handling: 47.689us +128 Text + +Decrypting Proteus. CheckingSession: 132.447us; Decrypting: 40.465699ms; Saving Session: 4.883us +Processing Application Message. LegalHold: 43.508220ms; Actually Handling: 84.078043ms; Post Handling: 43.498us +191 Text + +Decrypting Proteus. CheckingSession: 97.819us; Decrypting: 35.966390ms; Saving Session: 3.947us +Processing Application Message. LegalHold: 22.293782ms; Actually Handling: 82.308838ms; Post Handling: 41.015us +147 Text + +Decrypting Proteus. CheckingSession: 109.823us; Decrypting: 67.539388ms; Saving Session: 4.76us +Processing Application Message. LegalHold: 18.875651ms; Actually Handling: 39.499064ms; Post Handling: 41.422us +143 Text + +Decrypting Proteus. CheckingSession: 88.786us; Decrypting: 34.672689ms; Saving Session: 4.435us +Processing Application Message. LegalHold: 12.254029ms; Actually Handling: 59.550049ms; Post Handling: 42.155us +112 Text + +Decrypting Proteus. CheckingSession: 100.057us; Decrypting: 56.516113ms; Saving Session: 4.476us +Processing Application Message. LegalHold: 4.922648ms; Actually Handling: 43.885620ms; Post Handling: 40.935us +133 Text + +Decrypting Proteus. CheckingSession: 99.203us; Decrypting: 76.217733ms; Saving Session: 5.168us +Processing Application Message. LegalHold: 4.521729ms; Actually Handling: 74.523437ms; Post Handling: 65.186us +168 Text + +Decrypting Proteus. CheckingSession: 146.891us; Decrypting: 41.369263ms; Saving Session: 5.94us +Processing Application Message. LegalHold: 17.425049ms; Actually Handling: 160.854289ms; Post Handling: 369.913us +251 Text + +Decrypting Proteus. CheckingSession: 156.779us; Decrypting: 69.674438ms; Saving Session: 5.331us +Processing Application Message. LegalHold: 29.853068ms; Actually Handling: 32.974365ms; Post Handling: 44.556us +180 Text + +Decrypting Proteus. CheckingSession: 97.412us; Decrypting: 194.863933ms; Saving Session: 4.721us +Processing Application Message. LegalHold: 8.449300ms; Actually Handling: 110.715779ms; Post Handling: 47.607us +343 Text + +Decrypting Proteus. CheckingSession: 143.88us; Decrypting: 63.876993ms; Saving Session: 4.72us +Processing Application Message. LegalHold: 26.663046ms; Actually Handling: 100.153483ms; Post Handling: 43.01us +200 Text + +Decrypting Proteus. CheckingSession: 102.051us; Decrypting: 33.846557ms; Saving Session: 3.988us +Processing Application Message. LegalHold: 32.440105ms; Actually Handling: 77.101400ms; Post Handling: 50.13us +171 Text + +Decrypting Proteus. CheckingSession: 90.82us; Decrypting: 82.648763ms; Saving Session: 8.22us +Processing Application Message. LegalHold: 13.928873ms; Actually Handling: 59.246338ms; Post Handling: 74.911us +164 Text + +Decrypting Proteus. CheckingSession: 81.95us; Decrypting: 20.931438ms; Saving Session: 3.377us +Processing Application Message. LegalHold: 22.170573ms; Actually Handling: 54.304688ms; Post Handling: 60.628us +104 Text + +Decrypting Proteus. CheckingSession: 112.955us; Decrypting: 30.412068ms; Saving Session: 3.621us +Processing Application Message. LegalHold: 7.205160ms; Actually Handling: 56.475545ms; Post Handling: 48.869us +102 Text + +Decrypting Proteus. CheckingSession: 85.368us; Decrypting: 36.424520ms; Saving Session: 5.005us +Processing Application Message. LegalHold: 4.438477ms; Actually Handling: 30.431315ms; Post Handling: 40.771us +77 Text + +Decrypting Proteus. CheckingSession: 80.892us; Decrypting: 55.061971ms; Saving Session: 4.517us +Processing Application Message. LegalHold: 13.422851ms; Actually Handling: 23.873372ms; Post Handling: 40.243us +103 Text + +Decrypting Proteus. CheckingSession: 90.047us; Decrypting: 115.897624ms; Saving Session: 5.045us +Processing Application Message. LegalHold: 5.418457ms; Actually Handling: 63.461101ms; Post Handling: 41.667us +191 Text + +Decrypting Proteus. CheckingSession: 80.933us; Decrypting: 67.734945ms; Saving Session: 4.394us +Processing Application Message. LegalHold: 7.931397ms; Actually Handling: 45.393474ms; Post Handling: 39.795us +129 Text + +Decrypting Proteus. CheckingSession: 96.436us; Decrypting: 55.728027ms; Saving Session: 6.144us +Processing Application Message. LegalHold: 4.656291ms; Actually Handling: 82.777262ms; Post Handling: 55.502us +204 Text + +Decrypting Proteus. CheckingSession: 134.074us; Decrypting: 31.648315ms; Saving Session: 3.662us +Processing Application Message. LegalHold: 5.795695ms; Actually Handling: 41.531982ms; Post Handling: 40.894us +117 Text + +Decrypting Proteus. CheckingSession: 125.529us; Decrypting: 32.789713ms; Saving Session: 4.882us +Processing Application Message. LegalHold: 5.650310ms; Actually Handling: 23.350098ms; Post Handling: 41.178us +73 Text + +Decrypting Proteus. CheckingSession: 83.821us; Decrypting: 101.161296ms; Saving Session: 4.639us +Processing Application Message. LegalHold: 5.676758ms; Actually Handling: 84.787313ms; Post Handling: 42.643us +198 Text + +Decrypting Proteus. CheckingSession: 101.929us; Decrypting: 100.994466ms; Saving Session: 4.476us +Processing Application Message. LegalHold: 6.584229ms; Actually Handling: 44.870361ms; Post Handling: 43.701us +165 Text + +Decrypting Proteus. CheckingSession: 101.44us; Decrypting: 40.139079ms; Saving Session: 5.656us +Processing Application Message. LegalHold: 23.923584ms; Actually Handling: 73.660075ms; Post Handling: 40.161us +190 Text + +Decrypting Proteus. CheckingSession: 97.575us; Decrypting: 13.363729ms; Saving Session: 3.459us +Processing Application Message. LegalHold: 15.317383ms; Actually Handling: 19.124390ms; Post Handling: 45.573us +78 Text + +Decrypting Proteus. CheckingSession: 114.461us; Decrypting: 18.798991ms; Saving Session: 4.435us +Processing Application Message. LegalHold: 7.636108ms; Actually Handling: 95.518391ms; Post Handling: 62.418us +172 Text + +Decrypting Proteus. CheckingSession: 89.396us; Decrypting: 45.923869ms; Saving Session: 5.046us +Processing Application Message. LegalHold: 30.199504ms; Actually Handling: 31.469930ms; Post Handling: 57.617us +124 Text + +Decrypting Proteus. CheckingSession: 117.187us; Decrypting: 68.765584ms; Saving Session: 6.348us +Processing Application Message. LegalHold: 19.563192ms; Actually Handling: 70.637858ms; Post Handling: 68.074us +172 Text + +Decrypting Proteus. CheckingSession: 206.543us; Decrypting: 110.533895ms; Saving Session: 9.684us +Processing Application Message. LegalHold: 9.586548ms; Actually Handling: 19.422160ms; Post Handling: 44.719us +155 Text + +Decrypting Proteus. CheckingSession: 84.798us; Decrypting: 28.744751ms; Saving Session: 4.558us +Processing Application Message. LegalHold: 4.979573ms; Actually Handling: 18.377157ms; Post Handling: 39.998us +74 Text + +Decrypting Proteus. CheckingSession: 178.101us; Decrypting: 14.005493ms; Saving Session: 3.337us +Processing Application Message. LegalHold: 4.134807ms; Actually Handling: 30.131144ms; Post Handling: 38.492us +54 Text + +Decrypting Proteus. CheckingSession: 92.407us; Decrypting: 70.199544ms; Saving Session: 4.679us +Processing Application Message. LegalHold: 13.248739ms; Actually Handling: 114.933187ms; Post Handling: 39.998us +259 Text + +Decrypting Proteus. CheckingSession: 159.424us; Decrypting: 41.670899ms; Saving Session: 4.313us +Processing Application Message. LegalHold: 28.232829ms; Actually Handling: 16.727539ms; Post Handling: 36.621us +103 Text + +Decrypting Proteus. CheckingSession: 92.529us; Decrypting: 64.359416ms; Saving Session: 4.028us +Processing Application Message. LegalHold: 4.952107ms; Actually Handling: 14.338094ms; Post Handling: 54.932us +89 Text + +Decrypting Proteus. CheckingSession: 101.888us; Decrypting: 49.372478ms; Saving Session: 5.249us +Processing Application Message. LegalHold: 36.024455ms; Actually Handling: 41.159505ms; Post Handling: 43.905us +168 Text + +Decrypting Proteus. CheckingSession: 85.205us; Decrypting: 14.965413ms; Saving Session: 4.028us +Processing Application Message. LegalHold: 5.274007ms; Actually Handling: 32.183391ms; Post Handling: 44.271us +58 Text + +Decrypting Proteus. CheckingSession: 92.082us; Decrypting: 86.730713ms; Saving Session: 5.086us +Processing Application Message. LegalHold: 4.609131ms; Actually Handling: 38.390340ms; Post Handling: 45.166us +135 Text + +Decrypting Proteus. CheckingSession: 101.725us; Decrypting: 15.713461ms; Saving Session: 3.662us +Processing Application Message. LegalHold: 4.611979ms; Actually Handling: 47.136109ms; Post Handling: 50.904us +92 Text + +Decrypting Proteus. CheckingSession: 86.1us; Decrypting: 74.593669ms; Saving Session: 6.755us +Processing Application Message. LegalHold: 4.965617ms; Actually Handling: 26.958374ms; Post Handling: 41.015us +136 Text + +Decrypting Proteus. CheckingSession: 94.523us; Decrypting: 26.139405ms; Saving Session: 3.58us +Processing Application Message. LegalHold: 14.431519ms; Actually Handling: 46.557496ms; Post Handling: 3.227986ms +97 Text + +Decrypting Proteus. CheckingSession: 149.211us; Decrypting: 38.674520ms; Saving Session: 3.58us +Processing Application Message. LegalHold: 5.177002ms; Actually Handling: 76.428630ms; Post Handling: 78.125us +145 Text + +Decrypting Proteus. CheckingSession: 115.845us; Decrypting: 18.225139ms; Saving Session: 4.476us +Processing Application Message. LegalHold: 19.205403ms; Actually Handling: 76.934448ms; Post Handling: 62.622us +145 Text + +Decrypting Proteus. CheckingSession: 103.231us; Decrypting: 53.127604ms; Saving Session: 5.005us +Processing Application Message. LegalHold: 5.670289ms; Actually Handling: 56.225545ms; Post Handling: 58.675us +151 Text + +Decrypting Proteus. CheckingSession: 82.885us; Decrypting: 115.505900ms; Saving Session: 8.789us +Processing Application Message. LegalHold: 11.379720ms; Actually Handling: 99.572673ms; Post Handling: 122.192us +263 Text + +Decrypting Proteus. CheckingSession: 183.756us; Decrypting: 104.482625ms; Saving Session: 6.714us +Processing Application Message. LegalHold: 13.235555ms; Actually Handling: 78.640258ms; Post Handling: 54.525us +204 Text + +Decrypting Proteus. CheckingSession: 111.206us; Decrypting: 36.096680ms; Saving Session: 6.307us +Processing Application Message. LegalHold: 31.570028ms; Actually Handling: 24.436483ms; Post Handling: 46.712us +160 Text + +Decrypting Proteus. CheckingSession: 79.671us; Decrypting: 92.863240ms; Saving Session: 4.965us +Processing Application Message. LegalHold: 50.057739ms; Actually Handling: 69.449626ms; Post Handling: 61.482us +221 Text + +Decrypting Proteus. CheckingSession: 1.046183ms; Decrypting: 72.940877ms; Saving Session: 5.208us +Processing Application Message. LegalHold: 5.366862ms; Actually Handling: 11.162923ms; Post Handling: 38.615us +116 Text + +Decrypting Proteus. CheckingSession: 71.37us; Decrypting: 22.764160ms; Saving Session: 4.191us +Processing Application Message. LegalHold: 9.260538ms; Actually Handling: 45.517619ms; Post Handling: 43.132us +92 Text + +Decrypting Proteus. CheckingSession: 80.119us; Decrypting: 40.078939ms; Saving Session: 4.476us +Processing Application Message. LegalHold: 6.736613ms; Actually Handling: 83.116537ms; Post Handling: 42.521us +138 Text