https://kotlinlang.org logo
Join Slack
Powered by
Ktor 3.6 seems to have introduced a client perform...
# ktor
c
Ktor 3.6 seems to have introduced a client performance regression on Android here github.com/ktorio/ktor/commit/b07448a0790f… Older versions of Ktor on Android prior to 3.6 performed disk I/O when the HttpClient was constructed, but I could work around that by wrapping it in withContext(). With 3.6, the I/O on main happens when the first network call is made. It moves the problem to a much larger Ktor API surface area. Before I file an issue is there anything I’m missing here about how this was intended to work on Android?
👀 1
a
So the idea is to make the logger initialization lazy to avoid disk I/O on the client creation. Can you please explain what the issue is with initializing the SLF4J logger on the first network call?
a
cc @Osip Fatkullin
c
What I’m seeing is that Ktor 3.6 still triggers a strict mode violation on the main thread on Android, its just happening a bit later. It seems to be the first call to 
isTraceEnabled
is happening when the 
ContentNegotiation
plugin is enabled.
This is the trace
Copy code
android.os.strictmode.DiskReadViolation
  at android.os.StrictMode$AndroidBlockGuardPolicy.onReadFromDisk(StrictMode.java:1728)
  at libcore.io.BlockGuardOs.lseek(BlockGuardOs.java:242)
  at libcore.io.ForwardingOs.lseek(ForwardingOs.java:469)
  at java.io.RandomAccessFile.seek(RandomAccessFile.java:635)
  at java.util.zip.ZipFile$Source.readFullyAt(ZipFile.java:1507)
  at java.util.zip.ZipFile$Source.-$$Nest$mreadFullyAt(Unknown Source:0)
  at java.util.zip.ZipFile$ZipFileInputStream.initDataOffset(ZipFile.java:999)
  at java.util.zip.ZipFile$ZipFileInputStream.read(ZipFile.java:1015)
  at java.io.FilterInputStream.read(FilterInputStream.java:133)
  at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:291)
  at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:355)
  at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:181)
  at java.io.InputStreamReader.read(InputStreamReader.java:177)
  at java.io.BufferedReader.fill(BufferedReader.java:172)
  at java.io.BufferedReader.readLine(BufferedReader.java:337)
  at java.io.BufferedReader.readLine(BufferedReader.java:403)
  at java.util.ServiceLoader$LazyClassPathLookupIterator.parseLine(ServiceLoader.java:1086)
  at java.util.ServiceLoader$LazyClassPathLookupIterator.parse(ServiceLoader.java:1127)
  at java.util.ServiceLoader$LazyClassPathLookupIterator.nextProviderClass(ServiceLoader.java:1167)
  at java.util.ServiceLoader$LazyClassPathLookupIterator.hasNextService(ServiceLoader.java:1184)
  at java.util.ServiceLoader$LazyClassPathLookupIterator.hasNext(ServiceLoader.java:1238)
  at java.util.ServiceLoader$2.hasNext(ServiceLoader.java:1367)
  at org.slf4j.LoggerFactory.findServiceProviders(LoggerFactory.java:133)
  at org.slf4j.LoggerFactory.bind(LoggerFactory.java:195)
  at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:187)
  at org.slf4j.LoggerFactory.getProvider(LoggerFactory.java:511)
  at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:497)
  at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:446)
  at io.ktor.util.logging.KtorSimpleLoggerJvmKt$KtorSimpleLogger$1.logger_delegate$lambda$0(KtorSimpleLoggerJvm.kt:22)
  at io.ktor.util.logging.KtorSimpleLoggerJvmKt$KtorSimpleLogger$1$$ExternalSyntheticLambda0.invoke(D8$$SyntheticClass:0)
  at kotlin.SynchronizedLazyImpl.getValue(LazyJVM.kt:86)
  at io.ktor.util.logging.KtorSimpleLoggerJvmKt$KtorSimpleLogger$1.getLogger(KtorSimpleLoggerJvm.kt:21)
  at io.ktor.util.logging.KtorSimpleLoggerJvmKt$KtorSimpleLogger$1.isTraceEnabled(KtorSimpleLoggerJvm.kt:30)
  at io.ktor.util.logging.LoggerJvmKt.isTraceEnabled(LoggerJvm.kt:9)
  at io.ktor.client.plugins.contentnegotiation.ContentNegotiationKt.ContentNegotiation$lambda$0$convertRequest(ContentNegotiation.kt:415)
  at io.ktor.client.plugins.contentnegotiation.ContentNegotiationKt.access$ContentNegotiation$lambda$0$convertRequest(ContentNegotiation.kt:1)
  at io.ktor.client.plugins.contentnegotiation.ContentNegotiationKt$ContentNegotiation$2$1.invokeSuspend(ContentNegotiation.kt:378)
  at io.ktor.client.plugins.contentnegotiation.ContentNegotiationKt$ContentNegotiation$2$1.invoke(Unknown Source:17)
  at io.ktor.client.plugins.contentnegotiation.ContentNegotiationKt$ContentNegotiation$2$1.invoke(Unknown Source:8)
  at io.ktor.client.plugins.api.TransformRequestBodyHook$install$1.invokeSuspend(KtorCallContexts.kt:87)
  at io.ktor.client.plugins.api.TransformRequestBodyHook$install$1.invoke(Unknown Source:11)
  at io.ktor.client.plugins.api.TransformRequestBodyHook$install$1.invoke(Unknown Source:4)
  at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79)
  at io.ktor.util.pipeline.DebugPipelineContext.proceed(DebugPipelineContext.kt:57)
  at io.ktor.client.plugins.RequestError$install$1.invokeSuspend(HttpCallValidator.kt:165)
  at io.ktor.client.plugins.RequestError$install$1.invoke(Unknown Source:11)
  at io.ktor.client.plugins.RequestError$install$1.invoke(Unknown Source:4)
  at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79)
  at io.ktor.util.pipeline.DebugPipelineContext.proceed(DebugPipelineContext.kt:57)
  at io.ktor.client.plugins.SetupRequestContext$install$1.invokeSuspend$proceed(HttpRequestLifecycle.kt:42)
  at io.ktor.client.plugins.SetupRequestContext$install$1.access$invokeSuspend$proceed(Unknown Source:0)
  at io.ktor.client.plugins.SetupRequestContext$install$1$1.invoke(HttpRequestLifecycle.kt:42)
  at io.ktor.client.plugins.SetupRequestContext$install$1$1.invoke(HttpRequestLifecycle.kt:42)
  at io.ktor.client.plugins.HttpRequestLifecycleKt$HttpRequestLifecycle$1$1.invokeSuspend(HttpRequestLifecycle.kt:29)
  at io.ktor.client.plugins.HttpRequestLifecycleKt$HttpRequestLifecycle$1$1.invoke(Unknown Source:13)
  at io.ktor.client.plugins.HttpRequestLifecycleKt$HttpRequestLifecycle$1$1.invoke(Unknown Source:6)
  at io.ktor.client.plugins.SetupRequestContext$install$1.invokeSuspend(HttpRequestLifecycle.kt:42)
  at io.ktor.client.plugins.SetupRequestContext$install$1.invoke(Unknown Source:11)
  at io.ktor.client.plugins.SetupRequestContext$install$1.invoke(Unknown Source:4)
  at io.ktor.util.pipeline.DebugPipelineContext.proceedLoop(DebugPipelineContext.kt:79)
  at io.ktor.util.pipeline.DebugPipelineContext.proceed(DebugPipelineContext.kt:57)
  at io.ktor.util.pipeline.DebugPipelineContext.execute$ktor_utils(DebugPipelineContext.kt:63)
  at io.ktor.util.pipeline.Pipeline.execute(Pipeline.kt:93)
  at io.ktor.client.HttpClient.execute$ktor_client_core(HttpClient.kt:1420)
  at io.ktor.client.statement.HttpStatement.fetchResponse(HttpStatement.kt:205)
  at io.ktor.client.statement.HttpStatement.execute(HttpStatement.kt:99)
And I think I might have found a workaround similar to what I was doing before. I’m still testing this though.
Copy code
internal suspend fun newHttpClient() =
    withContext(<http://Dispatchers.IO|Dispatchers.IO>) {
        // touch off the main thread to avoid strict mode violation
        val _ = KtorSimpleLogger("io.ktor.client.HttpClient").isTraceEnabled
    }

    HttpClient {
        ...
    }
a
The above stack trace seems to be a part of a request execution (it starts with 
HttpStatement.execute
), so 
isTraceEnabled
must be called during pipeline execution, not during client or plugin initialization. Can you please describe the performance regression in more detail? Does making the request with a different dispatcher help to avoid the DiskReadViolation?
c
Are you suggesting that I wrap 
HttpClient.request
in a 
withContext(<http://Dispatchers.IO|Dispatchers.IO>)
? Strict mode violations on Android are a performance concern. In this case Ktor 3.6 seems to have moved the violation rather than resolved it. It’s not exactly a regression, just the same bug in a different place. But the API surface area that can trigger the violation is now larger.
a
Are you suggesting that I wrap 
HttpClient.request
in a 
withContext(<http://Dispatchers.IO|Dispatchers.IO>)
?
Yes.
c
That should make the strict mode violation go away. Are you suggesting this as a temporary workaround, or how the Ktor team expects all clients to interact with the API? Since Ktor’s 
HttpClient.request
is a suspend function, so I wouldn’t anticipate needing to think about dispatchers when calling it.
a
Unfortunately, I cannot reproduce StrictMode violation through the 
isTraceEnabled
, although, I can see one coming from the extensions of the Kotlinx serialization converter:
Copy code
at io.ktor.serialization.kotlinx.ExtensionsJvmKt.<clinit>(ExtensionsJvm.kt:14)
                                                                                                    	at io.ktor.serialization.kotlinx.ExtensionsKt.extensions(Extensions.kt:17)
                                                                                                    	at io.ktor.serialization.kotlinx.KotlinxSerializationConverter.<init>(KotlinxSerializationConverter.kt:30)
                                                                                                    	at io.ktor.serialization.kotlinx.KotlinxSerializationConverterKt.serialization(KotlinxSerializationConverter.kt:134)
                                                                                                    	at io.ktor.serialization.kotlinx.json.JsonSupportKt.json(JsonSupport.kt:60)
Can you please share a code snippet where an HTTP request is made?
c
Thanks—I’m still debugging exactly where it is coming from. Let me see what I can figure out. The client I have its a little complex 😅
This snippet from my project reproduces the issue
Copy code
internal suspend fun newHttpClient(isVerboseLogging: Boolean): HttpClient {
            val _ = KtorSimpleLogger("io.ktor.client.HttpClient").isTraceEnabled // Eagerly triggers service loader IO
            return withContext(getMultiplatformIoDispatcher()) {
                HttpClient {
                    configureJson()

                    if (isVerboseLogging) {
                        configureLogging(sensitiveJsonBodyFieldNames = setOf("password", "token"))
                    }

                    install(ResponseBodyLimit) {
                        maxResponseSizeBytes = MAX_RESPONSE_SIZE_BYTES
                    }

                    install(SSE)
                }
            }
        }
This is the workaround
Copy code
internal suspend fun newHttpClient(isVerboseLogging: Boolean): HttpClient {
            return withContext(getMultiplatformIoDispatcher()) {
                val _ = KtorSimpleLogger("io.ktor.client.HttpClient").isTraceEnabled // Eagerly triggers service loader IO
                HttpClient {
                    configureJson()

                    if (isVerboseLogging) {
                        configureLogging(sensitiveJsonBodyFieldNames = setOf("password", "token"))
                    }

                    install(ResponseBodyLimit) {
                        maxResponseSizeBytes = MAX_RESPONSE_SIZE_BYTES
                    }

                    install(SSE)
                }
            }
        }
a
As I can see, in both snippets, the 
isTraceEnabled
is accessed on the main thread. Can you please share a code snippet in which the client is constructed on the main thread without touching the logger (requests can be made on any dispatcher)?
c
The second snippet above is the workaround—it touches the logger off the main thread on Dispatchers.IO (the change is subtle). This third snippet triggers the issue I noticed with Ktor 3.6
Copy code
internal suspend fun newHttpClient(isVerboseLogging: Boolean): HttpClient {
     return withContext(getMultiplatformIoDispatcher()) {
         HttpClient {
             configureJson()

             if (isVerboseLogging) {
                 configureLogging(sensitiveJsonBodyFieldNames = setOf("password", "token"))
             }

             install(ResponseBodyLimit) {
                 maxResponseSizeBytes = MAX_RESPONSE_SIZE_BYTES
             }

             install(SSE)
         }
     }
}

// later in a suspend fun
val httpClient = newHttpClient(true)

httpClient.request(...) // Triggers service loader IO on main
a
Can you please tell me if you can reproduce the problem when the client is constructed on the main thread and the requests are fired on any dispatcher? Also, the logger is not intentionally accessed to eagerly trigger service loader IO.
c
And oops I just made an edit to the third example above.
I deleted the touching of ktorsimplelogger as it wasn’t supposed to be there. Trying to copy examples into slack blob sweat smile
To answer your last question the two ViewModel methods should hopefully make it clear
Copy code
class MyViewModel : ViewModel() {
    private val httpClient = newHttpClient(true)

    fun doRequestMain() {
        viewModelScope.launch {
            httpClient.request(...) // Triggers service loader IO strictmode violation
        }
    }

    fun doRequestIo() {
        viewModelScope.launch {
            withContext(<http://Dispatchers.IO|Dispatchers.IO>) {
                httpClient.request(...) // No strict mode violation because we're off the main thread now
            }
        }
    }
}

internal fun newHttpClient(isVerboseLogging: Boolean): HttpClient {
    return HttpClient {
        configureJson() // can trigger a different strictmode violation

        if (isVerboseLogging) {
            configureLogging(sensitiveJsonBodyFieldNames = setOf("password", "token"))
        }

        install(ResponseBodyLimit) {
            maxResponseSizeBytes = MAX_RESPONSE_SIZE_BYTES
        }

        install(SSE)
    }
}
a
Unfortunately, I cannot reproduce the problem with the following code:
Copy code
import android.os.Bundle
import android.os.StrictMode
import android.util.Log
import androidx.appcompat.app.AppCompatActivity
import androidx.lifecycle.ViewModel
import androidx.lifecycle.ViewModelProvider
import androidx.lifecycle.viewModelScope
import io.ktor.client.HttpClient
import io.ktor.client.call.body
import io.ktor.client.engine.cio.CIO
import io.ktor.client.plugins.contentnegotiation.ContentNegotiation
import <http://io.ktor.client.request.post|io.ktor.client.request.post>
import io.ktor.client.request.setBody
import io.ktor.http.ContentType
import io.ktor.http.contentType
import io.ktor.serialization.kotlinx.json.json
import kotlinx.coroutines.launch
import kotlinx.serialization.SerialName
import kotlinx.serialization.Serializable
import kotlinx.serialization.json.Json

@Serializable
data class EchoRequest(
    val message: String,
    val count: Int,
)

@Serializable
data class HttpBinResponse(
    val url: String,
    @SerialName("json") val json: EchoRequest? = null,
)

val client = HttpClient(CIO) {
    // ContentNegotiation is installed and used to (de)serialize JSON bodies.
    install(ContentNegotiation) {
        json(
            Json {
                ignoreUnknownKeys = true
                prettyPrint = true
            }
        )
    }
}

class MainViewModel : ViewModel() {
    fun load() {
        viewModelScope.launch {
            val response: HttpBinResponse = <http://client.post|client.post>("<https://httpbin.org/post>") {
                contentType(ContentType.Application.Json)
                setBody(EchoRequest(message = "test", count = 1))
            }.body()

            Log.i("HTTP", response.url)
        }
    }
}

class MainActivity : AppCompatActivity() {

    override fun onCreate(savedInstanceState: Bundle?) {
        StrictMode.setThreadPolicy(
            StrictMode.ThreadPolicy.Builder()
                .detectAll()
                .penaltyLog()
                .build()
        )
        StrictMode.setVmPolicy(
            StrictMode.VmPolicy.Builder()
                .detectAll()
                .penaltyLog()
                .build()
        )

        super.onCreate(savedInstanceState)

        setContentView(R.layout.activity_main)

        ViewModelProvider(this)[MainViewModel::class.java].load()
    }

    override fun onDestroy() {
        super.onDestroy()
    }
}
c
okay I’ll see if I can come up with a simple reproducible example, since those were contrived extractions from my project
Do you have sl4fj as a dependency for your example? e.g. 
_implementation_("org.slf4j:slf4j-jdk14:2.0.20")
MainActivity
Copy code
package com.example.ktorstrictmode

import android.app.Activity
import android.os.Bundle
import android.os.StrictMode
import android.util.Log
import android.widget.ScrollView
import android.widget.TextView
import io.ktor.client.HttpClient
import io.ktor.client.call.body
import io.ktor.client.engine.cio.CIO
import io.ktor.client.plugins.contentnegotiation.ContentNegotiation
import io.ktor.client.request.post
import io.ktor.client.request.setBody
import io.ktor.http.ContentType
import io.ktor.http.contentType
import io.ktor.serialization.kotlinx.json.json
import kotlinx.coroutines.CancellationException
import kotlinx.coroutines.Dispatchers
import kotlinx.coroutines.MainScope
import kotlinx.coroutines.cancel
import kotlinx.coroutines.launch
import kotlinx.coroutines.withContext
import kotlinx.serialization.SerialName
import kotlinx.serialization.Serializable
import kotlinx.serialization.json.Json

@Serializable
data class EchoRequest(
    @SerialName("message")
    val message: String,
    @SerialName("count")
    val count: Int,
)

@Serializable
data class HttpBinResponse(
    @SerialName("url")
    val url: String,
)

class MainActivity : Activity() {
    private val scope = MainScope()

    override fun onCreate(savedInstanceState: Bundle?) {
        super.onCreate(savedInstanceState)

        val output = TextView(this).apply { setTextIsSelectable(true) }
        setContentView(ScrollView(this).apply { addView(output) })

        StrictMode.setThreadPolicy(
            StrictMode.ThreadPolicy
                .Builder()
                .detectAll()
                .penaltyLog()
                .penaltyListener(mainExecutor) { violation ->
                    output.append("StrictMode violation on the main thread:\n${violation.stackTraceToString()}\n\n")
                }.build()
        )

        scope.launch {
            // Built off the main thread, as an app does to keep one-time setup off the UI thread.
            // With Ktor 3.5.2, this is where slf4j looks up its provider.
            val client =
                withContext(Dispatchers.IO) {
                    HttpClient(CIO) {
                        install(ContentNegotiation) {
                            json(Json { ignoreUnknownKeys = true })
                        }
                    }
                }

            // The request pipeline runs on the caller's dispatcher, Dispatchers.Main here. With Ktor
            // 3.6.0, the first logger check in it is where slf4j looks up its provider.
            client.use {
                try {
                    val response: HttpBinResponse =
                        it
                            .post("<https://httpbin.org/post>") {
                                contentType(ContentType.Application.Json)
                                setBody(EchoRequest(message = "test", count = 1))
                            }.body()
                    output.report("Request finished: ${response.url}")
                } catch (e: CancellationException) {
                    throw e
                } catch (e: Exception) {
                    output.report("Request failed: $e")
                }
            }
        }
    }

    override fun onDestroy() {
        scope.cancel()
        super.onDestroy()
    }
}

private fun TextView.report(message: String) {
    Log.i("KtorStrictModeRepro", message)
    append("$message\n\n")
}
Copy code
plugins {
    id("com.android.application")
    id("org.jetbrains.kotlin.plugin.serialization")
}

android {
    namespace = "com.example.ktorstrictmode"
    compileSdk = 36

    defaultConfig {
        applicationId = "com.example.ktorstrictmode"
        minSdk = 28
        targetSdk = 36
    }
}

dependencies {
    implementation("io.ktor:ktor-client-cio:3.6.0") // reproduces with either CIO or Android client
    implementation("io.ktor:ktor-client-content-negotiation:3.6.0")
    implementation("io.ktor:ktor-serialization-kotlinx-json:3.6.0")
    implementation("org.jetbrains.kotlinx:kotlinx-coroutines-android:1.11.0")

    // Any SLF4J 2 provider. Without one, slf4j finds no provider file in the APK to read, so
    // there is no disk read to flag.
    implementation("org.slf4j:slf4j-jdk14:2.0.20")
}
that code reproduces for me
a
Thanks. I've reproduced the problem. I am going to prepare the fix soon.
c
Awesome, thank you for working through this with me.
a
I've created an issue (KTOR-9972)
I've created a pull request to fix the problem. Can you please review the changes?
c
Thanks for quickly looking into this and designing a potential fix. The approach is straightforward and in practice it would resolve most instances of the strict mode violation. It is best effort rather than guaranteed (the code comment recognizes this), which does give me pause. You’ve got more insight into Ktor but I was trying to think broadly about other possibilities and came up with some alternatives (not all great but having options is good) Since Ktor’s public methods are suspend methods, could they do an internal check on the logger? Rough sketch:
Copy code
// ktor-utils (JVM)
private val slf4jInit: Deferred<Unit> by lazy {
    GlobalScope.async(<http://Dispatchers.IO|Dispatchers.IO>) { runCatching { LoggerFactory.getILoggerFactory() }; Unit }
}

@InternalAPI
public suspend fun awaitLoggerInitialization() {
    if (isAndroid && !slf4jInit.isCompleted) slf4jInit.await()
}

// ktor-client-core
internal suspend fun execute(builder: HttpRequestBuilder): HttpClientCall {
    awaitLoggerInitialization()
    monitor.raise(HttpRequestCreated, builder)
    return requestPipeline.execute(builder, builder.body) as HttpClientCall
}
The problem is that KtorSimpleLogger is public and this doesn’t address all usage, so would be incomplete but at least deterministic. Could Ktor wrap the logger with a 
SubstituteLoggerFactory
which buffers messages until an asynchronous init is complete and guaranteeing no violation? Could the 
ServiceLoader
be bypassed with 
System.setProperty(LoggerFactory.PROVIDER_PROPERTY_KEY, classname)
. This seems potentially brittle though.
a
In theory, the problem can be solved that way, but I think such changes to satisfy the strict-mode checker on Android are way too invasive. I would rather invent an Android-specific API to satisfy the checker and/or document the workaround.
6 Views
Open in Slack
PreviousNext
Powered by