Moshi: When using MoshiConverterFactory in retrofit, the first call blocks main thread

[Phocacius]

I am using the MoshiConverterFactory in an Android Application written in Kotlin in combination with Retrofit. The first call to retrofit's enqueue does not return directly like expected, but takes between one and two seconds to return blocking the UI thread and skipping up to 100 frames.
The problem only occurs when using Moshi, with Gson as Adapter Factory the first call takes longer too, but only around 150ms.

The code I'm using is:

val time = measureTimeMillis {
    val call = geocodingApi.searchByName("Berlin")
    call.enqueue(object : Callback<GeocodingResponse> {
        override fun onResponse(call: Call<GeocodingResponse>?, response: Response<GeocodingResponse>?) {
          // some code
        }

        override fun onFailure(call: Call<GeocodingResponse>?, t: Throwable?) {
          // some code
        }

    })
}
Timber.d("searching by name took $time ms")

The geocodingApi is initialised in the constructor of my class as follows:

val loggingInterceptor = HttpLoggingInterceptor(HttpLoggingInterceptor.Logger { Timber.d(it) })
loggingInterceptor.level = HttpLoggingInterceptor.Level.HEADERS

val client = OkHttpClient
        .Builder()
        .addInterceptor(loggingInterceptor)
        .addInterceptor(GoogleApiKeyInterceptor())
        .build()

val retrofit = Retrofit.Builder()
        .baseUrl(BASE_URL)
        .addConverterFactory(ScalarsConverterFactory.create())
        .addConverterFactory(MoshiConverterFactory.create(Moshi.Builder().add(KotlinJsonAdapterFactory()).build()))
        .client(client)
        .build()

geocodingApi = retrofit.create(GeocodingApi::class.java)

The logs look like this:

searching by name took 1864 ms
searching by name took 3 ms
searching by name took 4 ms
searching by name took 2 ms

I created a sample application to verify the behaviour without my app code: https://github.com/Phoca/KotlinRetrofitMoshiTest

Thanks for investigating!

[NightlyNexus]

I haven't downloaded your code yet, but you're creating your OkHttpClient and your Retrofit service lazily, so they'll be created on their first lookup: https://github.com/Phoca/KotlinRetrofitMoshiTest/blob/bc50ebc24581e90c22fa98ea5d984661c1017254/app/src/main/java/de/thorstenhack/moshiretrofittest/ApiManagerMoshi.kt#L22

Those are not cheap creations. The only thing that I could think of right now that would cause Moshi to be any different from Gson here is if new Gson is slightly quicker than new Moshi.Builder().build().

[Phocacius]

Unfortunately the creation of the retrofit objects is not the source of the problem.

I added an application class that accesses the managers without actually doing anything with them, but creating the objects: https://github.com/Phoca/KotlinRetrofitMoshiTest/blob/master/app/src/main/java/de/thorstenhack/moshiretrofittest/App.kt

This gives me the following output when starting the app:

D/App: init moshi took 119 ms
D/App: init gson took 30 ms 

However, when swapping the order of the calls (i.e. init ApiManagerGson first, then ApiManagerMoshi) it's approximately the same times, just the other way round. So when creating the retrofit objects, there's no difference.

Still, the problems persists, that when executing the first call, Moshi is very slow.
When executing a Gson call first, then a Moshi call, log is as follows:

execute with gson returned after 41 ms
execute with moshi returned after 1239 ms

It's even worse when I start with Moshi, and execute the Gson call afterwards:

execute with gson returned after 1298 ms
execute with moshi returned after 19 ms

The second call is always returning right away (after about two milliseconds).

[swankjesse]

Wanna use a profiler to get a breakdown of what's happening? Maybe class loading or a static initializer is to blame.

[Phocacius]

Sorry, I didn't use the profiler a lot so far. I couldn't find a way to save the profiling output, so I'm attaching screenshots. The delay can't be broken down to a single method, instead there is a never-ending call stack that I couldn't even display on the screen in full, and apparently I cannot scroll horizontally either. The first two screenshots are from the top-down view, the third from the bottom-up view. Kotlin's intrinsics seem to take quite a lot of time here.

The columns are Method time in µs / percentage, child time in µs / percentage and overall time in µs / percentage

[swankjesse]

Does the problem go away if you try Kotshi ? It might be due to the fact that Moshi uses Kotlin reflection, and Kotlin reflection is not particularly fast.

[Phocacius]

I just tried to implement Kotshi (see commit https://github.com/Phoca/KotlinRetrofitMoshiTest/commit/9539299b9919dd864742d755da263a11dd574c21), however I can't get it to run. I'm getting the error message

Error:(45, 2) error: Kotshi: Could not find a field named p4_1990234817 or a getter named getP4_1990234817
    de.thorstenhack.moshiretrofittest.Owner owner, boolean p4_1990234817) {
                                                           ^

Even when commenting out the owner field, the same error message stating a weird field id can't be found occurs for a simple String.

[LouisCAD]

@Phoca Could you post the whole error output please?

[Phocacius]

@LouisCAD I've investigated a bit further and found out that the issue was caused by a boolean field within the data class called private. Apparently the annotation processor converted this to p4_1990234817 which couldn't be found afterwards. Should I open an issue in the Kotshi repo?

@swankjesse Using Kotshi indeed fixed my problem. In the 1:1 comparison Gson is still a bit faster for me, but it's only a matter of milliseconds. Thanks for your help! It would be good to mention Kotshi in the Kotlin support section of the Readme.

[LouisCAD]

@Phoca You should open the issue to Kotshi repo, yes

[LouisCAD]

@Phoca

Using Kotshi indeed fixed my problem. In the 1:1 comparison Gson is still a bit faster for me, but it's only a matter of milliseconds.

About how many milliseconds?

[JakeWharton]

More importantly, how are you testing?

On Fri, Jan 19, 2018, 9:46 AM Louis CAD [e-mail] wrote:

@Phoca https://github.com/phoca

Using Kotshi indeed fixed my problem. In the 1:1 comparison Gson is still
a bit faster for me, but it's only a matter of milliseconds.

About how many milliseconds?

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/square/moshi/issues/362#issuecomment-358985541, or mute
the thread
https://github.com/notifications/unsubscribe-auth/AAEEEfXkVZogPVcslvZ2ejF5op-M3Howks5tMKrUgaJpZM4PygmE
.

[ansman]

@Phoca That is a known issue in Kotshi, it will be completely fixed when https://github.com/ansman/kotshi/issues/46 is resolved. For now you can work around it by either renaming it or doing this: https://github.com/ansman/kotshi/blob/master/tests/src/main/kotlin/se/ansman/kotshi/ClassWithJavaKeyword.kt

[Phocacius]

@ansman alright, thanks for the info!

@JakeWharton I was using the test app I linked above that uses the same api, same retrofit initialisation routine (except for the AdapterFactory of course) and model for both Moshi and Gson and just ran it multiple times. The time is measured using the measureTimeMillis method built into Kotlin. I didn't write down the exact values, but on average it was around 40ms for Gson and 45ms for Moshi. I can do a more thorough test using multiple devices tomorrow.

From my side the issue is resolved by using Kotshi, so feel free to close the issue. I'll still post the results of my analysis here.

[JakeWharton]

Got it. Thanks. This is actually a Retrofit bug (already filed), as it should be lazily initializing this on first usage and on a background thread (if you used enqueue). That being said, I think we're comfortable with Moshi taking a longer time to initialize an adapter (a one time cost) provided that the actual serialization cost paid over and over is less.

[hereisderek]

+1

[NightlyNexus]

Consider using a lazy ResponseBody converter?

public final class DeferredResponseBodyConverterFactory extends Converter.Factory {
  @Override
  public Converter<ResponseBody, ?> responseBodyConverter(Type type, Annotation[] annotations,
      Retrofit retrofit) {
    return new DeferredResponseBodyConverter(type, annotations, retrofit);
  }

  final class DeferredResponseBodyConverter implements Converter<ResponseBody, Object> {
    final Type type;
    final Annotation[] annotations;
    final Retrofit retrofit;
    volatile @Nullable Converter<ResponseBody, ?> delegate;

    DeferredResponseBodyConverter(Type type, Annotation[] annotations,
        Retrofit retrofit) {
      this.type = type;
      this.annotations = annotations;
      this.retrofit = retrofit;
    }

    @Override public Object convert(ResponseBody value) throws IOException {
      Converter<ResponseBody, ?> delegate = this.delegate;
      if (delegate == null) {
        delegate = retrofit.nextResponseBodyConverter(
            DeferredResponseBodyConverterFactory.this, type, annotations);
        this.delegate = delegate;
      }
      return delegate.convert(value);
    }
  }
}

unsure what Moshi itself can do here.

[ShoMasegi]

@Phoca Do you use "reserved word" at fourth param?
error: Kotshi: Could not find a field named p4_1990234817 or a getter named getP4_1990234817
This error would occur because of using reserved word.

[Phocacius]

@ShoMasegi Yes, I was using a field named private.
I already found out this was the cause of the problem, but thanks for the help.

Since my original issue is resolved now (for the Googlers with the same problem only reading the last message: Use Kotshi) I'm going to close this issue now. Thanks for your help!

[ArcherEmiya05]

Good day, I am facing the same issue when switching between fragment there is this noticeable freeze. What is the best solution so far?