black video thumbnails

[Michi Henning]

I have about 30 photos and 30 videos on the phone.

When starting the gallery app, I scroll the carousel all the way to the right, to force all thumbnails to be loaded. (That's while there are still lots of spinners shown.) All the videos appear at the right-hand end of the carousel. Most of them have good thumbnails but, randomly, a few of them show a black thumbnail.

Looking in the cache, we do not report any failures or other errors. When looking at the cache with thumbnailer-admin, I see that we have cached a completely black image in the full-size cache. The only way for that to happen is if vs-thumb gives us a black thumbnail without reporting an error.

Looks like streamer is to blame. (I'm seeing this with two concurrent vs-thumbs running.)

[Michi Henning (michihenning)]

This also happens with a max-extractions set to 1.

I'm also occasionally seeing the default music thumbnail that Victor reported. But, on scrolling the carousel, that one goes away and is replaced by the correct thumbnail (or a black one, where we have cached a black one).

dbus log shows nothing but successes for the thumbnailer.

[Michi Henning (michihenning)]

The attached screenshot shows both problems. Interestingly, when I scroll the carousel left, so the three default icons are no longer visible, and the scroll right again, the correct thumbnails appear. The cache reports that these were produced from a hit. This strongly suggests that the default icon that is displayed is incorrectly produced by the gallery app.

[Michi Henning (michihenning)]

It looks like the gallery app times out after a while and then displays the "missing art" icon.

It shouldn't be doing that. On the initial load of the app with a cold cache, we need to thumbnail loads of photos and videos. On a Mako, that takes quite some time. We are parallelizing this as much as possible already but, if there are many videos, the last one can take more than 30 seconds to show up.

The thumbnailer *will* eventually come up with a thumbnail, so there is no point in timing out in the calling app.

[Michi Henning (michihenning)]

So, when a black thumbnail happens, I see this in the gallery-app log:

ThumbnailerImageResponse::dbus_call_finished(): D-Bus error: "Handler::create_finished(): unity::ResourceException: RequestBase::thumbnail(): key = /home/phablet/Videos/com.ubuntu.camera/video20150604_035125835.mp4\0556047\01433389892.339516360\01433389892.339516360:
    VideoScreenshotter::data(): Video extractor pipeline failed"

We certainly need to improve logging in the thumbnailer. I want to see messages such as this in the thumbnailer log, not the application log. I'll add relevant debug to our code.

[Michi Henning (michihenning)]

Also just spotted this, after adding a bunch more videos to the Videos directory:

ThumbnailerImageResponse::dbus_call_finished(): D-Bus error: "Handler::create_finished(): unity::ResourceException: RequestBase::thumbnail(): key = /home/phablet/Videos/com.ubuntu.camera/1.mp4\0556085\01433986922.237337000\01433986922.237337000:
    VideoScreenshotter::data(): vs-thumb subprocess crashed"
libust[1988/2009]: Error: Error opening shm /lttng-ust-wait-5-32011 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[1988/2008]: Error: Error opening shm /lttng-ust-wait-5 (in get_wait_shm() at lttng-ust-comm.c:958)
ThumbnailerImageResponse::dbus_call_finished(): D-Bus error: "Handler::create_finished(): unity::ResourceException: RequestBase::thumbnail(): key = /home/phablet/Videos/com.ubuntu.camera/8.mp4\0556165\01433986924.69291831\01433986924.69291831:
    VideoScreenshotter::data(): vs-thumb subprocess crashed"

There are two such messages and, on screen, I see two icons that show the "no artwork found icon". So, it appears that the no artwork found icons are not due to timeouts, but due to gstreamer falling over.

[Michi Henning (michihenning)]

Hmmm... This is not looking good. So, I have 53 videos in my Videos directory. Each video is a few seconds long, around 5 MB in size each. I wipe the cache and start the gallery app, and scroll around to push requests to the thumbnailer. Then after a while, I see this in the log:

thumbnailer-service: [01:53:35.041] "thumbnail: /home/phablet/Pictures/com.ubuntu.camera/image20150604_035240355.jpg (256,0): 1.853746 sec (HIT)"
thumbnailer-service: [01:53:35.066] "thumbnail: /home/phablet/Pictures/com.ubuntu.camera/image20150604_035243108.jpg (256,0): 1.877430 sec (HIT)"
thumbnailer-service: [01:53:35.081] "thumbnail: /home/phablet/Pictures/com.ubuntu.camera/image20150604_035217055.jpg (256,0): 1.864489 sec (HIT)"

(vs-thumb:7164): GLib-ERROR **: /build/buildd/glib2.0-2.45.1/./glib/gmem.c:357: overflow allocating 4294967274*8 bytes

(vs-thumb:7152): GLib-ERROR **: /build/buildd/glib2.0-2.45.1/./glib/gmem.c:357: overflow allocating 4294967274*8 bytes

(vs-thumb:7177): GLib-ERROR **: /build/buildd/glib2.0-2.45.1/./glib/gmem.c:357: overflow allocating 4294967274*8 bytes

(vs-thumb:7166): GLib-ERROR **: /build/buildd/glib2.0-2.45.1/./glib/gmem.c:357: overflow allocating 4294967274*8 bytes
thumbnailer-service: [01:53:35.152] "thumbnail: /home/phablet/Pictures/com.ubuntu.camera/image20150604_035221468.jpg (256,0): 1.936395 sec (HIT)"

(vs-thumb:7170): GLib-ERROR **: /build/buildd/glib2.0-2.45.1/./glib/gmem.c:357: overflow allocating 4294967274*8 bytes

(vs-thumb:7165): GLib-ERROR **: /build/buildd/glib2.0-2.45.1/./glib/gmem.c:357: overflow allocating 4294967274*8 bytes
thumbnailer-service: [01:53:35.206] "thumbnail: /home/phablet/Pictures/com.ubuntu.camera/image20150604_035215563.jpg (256,0): 1.989531 sec (HIT)"

So, something repeatedly tries to allocate 24 GB of memory. I'm not impressed :-(

[Michi Henning (michihenning)]

Since we limited concurrent extractions to 1 on Arm, this has not happened again. Closing as fixed.