coil-kt / coil

Image loading for Android and Compose Multiplatform.
https://coil-kt.github.io/coil/
Apache License 2.0
10.75k stars 657 forks source link

Drawing is pending on network request #1476

Closed lawm closed 2 years ago

lawm commented 2 years ago

Description Coil is very useful. Thanks for creating and maintaining it.

I edited the sample app to use URLs like this: https://192.168.10.94:8000/nothing.jpg

192.168.10.94 is a valid host, but the web server is not running, meaning it is not accepting incoming connections to port 8000.

Here is the Timestamp: and Description of what happens in the video: 0 sec: I start the app 4 sec: dark blue placeholder colors are shown. This is expected. 10 sec: Red error color is shown, as configured. This is expected. 12 sec: I click "JPG" to switch to MP4 list. 14 sec: I click "MP4" to switch back to "JPG" list. The problem is here. The UI thread seems to be blocked and nothing new is drawn. The placeholder color is not shown, and the "JPG" list isn't drawn.

20 sec: It shows the JPG list with Red error Drawables.

If I use an invalid host, like 192.168.1.123, which doesn't exist on my network, the issue does not happen. I think it's because the network failure is returned faster in this case compared to when the host is valid and not accepting connections or returning packets.

Video:

https://user-images.githubusercontent.com/3174101/192216374-5a53fca2-a506-40ce-abd5-a1b48a71ef99.mov

Steps To Reproduce Checkout my branch or cherry-pick my change: https://github.com/lawm/coil/commits/bug-repro-hang-on-network-request Edit coil-sample-common/src/main/assets/jpgs.json. Change the urls to your PC's IP address, and don't run any web server. Start app, wait for red error color. Click "JPG" Click "MP4" Watch app hang for 4 seconds until red error color is drawn.

Log

Expand ``` ---------------------------- PROCESS STARTED (23814) for package coil.sample ---------------------------- 2022-09-25 23:12:16.866 23814-23838 OpenGLRenderer coil.sample D HWUI GL Pipeline 2022-09-25 23:12:17.132 23814-23819 zygote coil.sample I Do partial code cache collection, code=29KB, data=20KB 2022-09-25 23:12:17.134 23814-23819 zygote coil.sample I After code cache collection, code=29KB, data=20KB 2022-09-25 23:12:17.134 23814-23819 zygote coil.sample I Increasing code cache capacity to 128KB 2022-09-25 23:12:17.284 23814-23819 zygote coil.sample I Do partial code cache collection, code=59KB, data=45KB 2022-09-25 23:12:17.287 23814-23819 zygote coil.sample I After code cache collection, code=59KB, data=45KB 2022-09-25 23:12:17.287 23814-23819 zygote coil.sample I Increasing code cache capacity to 256KB 2022-09-25 23:12:17.376 23814-23838 coil.sample D HostConnection::get() New Host Connection established 0xa3b21640, tid 23838 2022-09-25 23:12:17.379 23814-23838 zygote coil.sample I android::hardware::configstore::V1_0::ISurfaceFlingerConfigs::hasWideColorDisplay retrieved: 0 2022-09-25 23:12:17.379 23814-23838 OpenGLRenderer coil.sample I Initialized EGL, version 1.4 2022-09-25 23:12:17.379 23814-23838 OpenGLRenderer coil.sample D Swap behavior 1 2022-09-25 23:12:17.379 23814-23838 OpenGLRenderer coil.sample W Failed to choose config with EGL_SWAP_BEHAVIOR_PRESERVED, retrying without... 2022-09-25 23:12:17.379 23814-23838 OpenGLRenderer coil.sample D Swap behavior 0 2022-09-25 23:12:17.381 23814-23838 EGL_emulation coil.sample D eglCreateContext: 0xa4db2300: maj 3 min 0 rcv 3 2022-09-25 23:12:17.385 23814-23838 EGL_emulation coil.sample D eglMakeCurrent: 0xa4db2300: ver 3 0 (tinfo 0xa64b2260) 2022-09-25 23:12:17.411 23814-23814 Compose Focus coil.sample D Owner FocusChanged(true) 2022-09-25 23:12:17.443 23814-23814 Choreographer coil.sample I Skipped 32 frames! The application may be doing too much work on its main thread. 2022-09-25 23:12:17.464 23814-23838 EGL_emulation coil.sample D eglMakeCurrent: 0xa4db2300: ver 3 0 (tinfo 0xa64b2260) 2022-09-25 23:12:17.648 23814-23819 zygote coil.sample I Do full code cache collection, code=120KB, data=98KB 2022-09-25 23:12:17.648 23814-23819 zygote coil.sample I After code cache collection, code=120KB, data=78KB 2022-09-25 23:12:17.661 23814-23860 NetworkObserver coil.sample I ONLINE 2022-09-25 23:12:17.664 23814-23814 sample coil.sample D onLoading 2022-09-25 23:12:17.691 23814-23814 chatty coil.sample I uid=10091(coil.sample) identical 1 line 2022-09-25 23:12:17.704 23814-23814 sample coil.sample D onLoading 2022-09-25 23:12:17.711 23814-23819 zygote coil.sample I Do partial code cache collection, code=121KB, data=90KB 2022-09-25 23:12:17.721 23814-23819 zygote coil.sample I After code cache collection, code=121KB, data=91KB 2022-09-25 23:12:17.721 23814-23819 zygote coil.sample I Increasing code cache capacity to 512KB 2022-09-25 23:12:17.860 23814-23847 Networ...Config coil.sample D No Network Security Config specified, using platform default 2022-09-25 23:12:21.888 23814-23814 RealImageLoader coil.sample I 🚨 Failed - https://192.168.10.94:8000/nothing2.jpg - java.net.ConnectException: Failed to connect to /192.168.10.94:8000 2022-09-25 23:12:21.889 23814-23814 sample coil.sample D onError 2022-09-25 23:12:23.906 23814-23814 RealImageLoader coil.sample I 🚨 Failed - https://192.168.10.94:8000/nothing3.jpg - java.net.ConnectException: Failed to connect to /192.168.10.94:8000 2022-09-25 23:12:23.907 23814-23814 sample coil.sample D onError 2022-09-25 23:12:23.949 23814-23814 RealImageLoader coil.sample I 🚨 Failed - https://192.168.10.94:8000/nothing.jpg - java.net.ConnectException: Failed to connect to /192.168.10.94:8000 2022-09-25 23:12:23.949 23814-23814 sample coil.sample D onError 2022-09-25 23:12:23.963 23814-23869 Profil...taller coil.sample D Installing profile for coil.sample // Clicked "JPG" at 00:12sec in the video to switch to MP4 list. 2022-09-25 23:12:25.929 23814-23814 sample coil.sample D onClick 2022-09-25 23:12:25.973 23814-23814 sample coil.sample D onLoading 2022-09-25 23:12:26.085 23814-23814 RealImageLoader coil.sample I 💾 Successful (DISK) - file:///android_asset/video.mp4 2022-09-25 23:12:26.109 23814-23819 zygote coil.sample I Do full code cache collection, code=245KB, data=189KB 2022-09-25 23:12:26.109 23814-23819 zygote coil.sample I After code cache collection, code=236KB, data=144KB // Clicked "MP4" at 00:14sec in the video to switch back to JPG list. Issue is here. Drawing hangs for 4 seconds. 2022-09-25 23:12:28.242 23814-23814 sample coil.sample D onClick 2022-09-25 23:12:28.247 23814-23819 zygote coil.sample I Do partial code cache collection, code=243KB, data=157KB 2022-09-25 23:12:28.247 23814-23819 zygote coil.sample I After code cache collection, code=243KB, data=157KB 2022-09-25 23:12:28.247 23814-23819 zygote coil.sample I Increasing code cache capacity to 1024KB 2022-09-25 23:12:28.280 23814-23814 sample coil.sample D onLoading 2022-09-25 23:12:30.317 23814-23814 sample coil.sample D onLoading 2022-09-25 23:12:32.340 23814-23814 sample coil.sample D onLoading 2022-09-25 23:12:34.367 23814-23814 Choreographer coil.sample I Skipped 365 frames! The application may be doing too much work on its main thread. 2022-09-25 23:12:34.374 23814-23814 RealImageLoader coil.sample I 🚨 Failed - https://192.168.10.94:8000/nothing.jpg - java.net.ConnectException: Failed to connect to /192.168.10.94:8000 2022-09-25 23:12:34.375 23814-23814 sample coil.sample D onError 2022-09-25 23:12:34.375 23814-23814 RealImageLoader coil.sample I 🚨 Failed - https://192.168.10.94:8000/nothing3.jpg - java.net.ConnectException: Failed to connect to /192.168.10.94:8000 2022-09-25 23:12:34.376 23814-23814 sample coil.sample D onError 2022-09-25 23:12:34.377 23814-23814 RealImageLoader coil.sample I 🚨 Failed - https://192.168.10.94:8000/nothing2.jpg - java.net.ConnectException: Failed to connect to /192.168.10.94:8000 2022-09-25 23:12:34.377 23814-23814 sample coil.sample D onError 2022-09-25 23:12:37.643 23814-23838 EGL_emulation coil.sample D eglMakeCurrent: 0xa4db2300: ver 3 0 (tinfo 0xa64b2260) ```

Version Latest coil main branch as of today.

colinrtwhite commented 2 years ago

@lawm Your test branch works ok for me:

test.webm

lawm commented 2 years ago

Thanks for trying it.

I did some more tests on new emulator instances, a real device, and different urls.

It happens with this combination: macOS with LuLu firewall enabled, running an Android emulator, and the URL is any local network device that is on the network, but doesn't have a web server running.

If I use a real Android 6.0 device, the issue doesn't happen. If I disable the LuLu firewall, the issue doesn't happen. On new emulator instances, I may need to try clicking JPG/MP4 a few times (not fast, just switching back and forth), and it will sometimes show the placeholder, but the JPG/MP4 click ripple animation is frozen for ~2 seconds. Using a URL to a Linux laptop's IP address, the issue also happens.

The emulator and firewall combination causes something (the app or some emulator resource) to hang.

I tried to use the Android Studio profiler.

One type of trace shows android.os.MessageQueue.nativePollOnce taking 6 seconds. DefaultDispatcher and OkHttp threads also take ~6 seconds in the same timeframe.

image

image image image OkHttp Dispatcher Flame Chart: image

Another type of trace just shows recomposing and drawing: image

I want to try inserting a Thread.sleep() somewhere in the above OkHttp call path to simulate this without the firewall. But, even with that, I would still need to figure out how the OkHttp thread blocks the UI.

lawm commented 2 years ago

I can't figure it out and maybe it's a problem in the emulator, not coil. We can close this issue for now.