crop temporarily hangs the app since simple-scan uses sqlite

[Tim Abell]

Hi, I've built trunk from source (rev 603) and am running that build on Ubuntu 12.04 LTS 64bit. (As part of working on bug 897469)

This doesn't happen all the time, but quite often when I hit the "crop" button, and for each crop action after that (drag the crop area, resize the crop area), simple scan become unresponsive. After a pause ubuntu dims the simple scan window. Then a couple of minutes later the app becomes responsive again.

Let me know if there's any info I can provide to help troubleshoot this issue.

Thanks

Tim

[Thierry-vignaud (thierry-vignaud)]

I confirm this bug: since updating Mageia Cauldrom from 3.6.x to 3.8.x, simple-scan is painfully slow as soon as I tried to crop a scan. I can heard the hard disk being hit whereas I've 3Gb of RAM, no other app running and I use a rather slow definition.

I note that simple-scan-3.8.0 now uses sqlite (though that's not in the NEWS file). Maybe an hint?
We're using sqlite 3.7.16

[Thierry-vignaud (thierry-vignaud)]

And indeed there's now a lot of writing into ~/.cache/simple-scan/autosaves/

There's a 103Mb autosaves.db file there.

When cropping, simple-scan loops on :
- creating a second file (autosaves.db-journal)
- writing scores of Mb into it
- fsync() it
- removing it

When removing it, on first scan, it got recreated with lots of I/O including fsync(), even before actually clicking on the "crop" button.
When actually trying to crop, it got slow as hell again.

[Thierry-vignaud (thierry-vignaud)]

And I confirm than making a tmpfs out of that directory make simple-scan fast again:
sudo mount -t tmpfs none ~/.cache/simple-scan/autosaves/

[Michael Nagel (nailor)]

Timo, please have a look at this.

[Michael Nagel (nailor)]

ps: the sqlite thing was not announced properly. see

Simple Scan crashes result in preventable data loss
Simple Scan Bugs Bug #897469

[Thierry-vignaud (thierry-vignaud)]

Trading data loss when crashing between scan & saving vs slow to death croping is not nice:
1) we should be able to disable that behavior in the GUI
2) it should not save any data at all while we're cropping
    at least not when we're just moving the mouse cursor on the screen

[Michael Nagel (nailor)]

imho the autosaves should not slow down cropping; this is not an either-or decision where we can only have one, but probably a bug in the new autosaving code. this should be fixed.

[Thierry-vignaud (thierry-vignaud)]

Ping?

[TJ (tj)]

Confirmed here too:

After deleting the autosave cache files, scanning a single Letter page, and selecting Crop the application spins unresponsively driving one core of the CPU hard for many seconds and repeats that after each subsequent mouse operation, preventing me from interacting with the crop function.

Program received signal SIGINT, Interrupt.
0x00007ffff546ecbd in read () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007ffff546ecbd in read () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007ffff6018a86 in ?? () from /usr/lib/x86_64-linux-gnu/libsqlite3.so.0
#2 0x00007ffff602c158 in ?? () from /usr/lib/x86_64-linux-gnu/libsqlite3.so.0
#3 0x00007ffff603ec19 in ?? () from /usr/lib/x86_64-linux-gnu/libsqlite3.so.0
#4 0x00007ffff603ec78 in ?? () from /usr/lib/x86_64-linux-gnu/libsqlite3.so.0
#5 0x00007ffff604b9d9 in ?? () from /usr/lib/x86_64-linux-gnu/libsqlite3.so.0
#6 0x00007ffff604f18c in ?? () from /usr/lib/x86_64-linux-gnu/libsqlite3.so.0
#7 0x00007ffff6053a51 in ?? () from /usr/lib/x86_64-linux-gnu/libsqlite3.so.0
#8 0x00007ffff607f617 in ?? () from /usr/lib/x86_64-linux-gnu/libsqlite3.so.0
#9 0x00007ffff6063341 in sqlite3_step () from /usr/lib/x86_64-linux-gnu/libsqlite3.so.0
#10 0x000000000042fb02 in autosave_manager_update_page (self=<optimised out>, page=0x6b52d0) at autosave-manager.c:1423
#11 0x00007ffff65b4620 in g_closure_invoke () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#12 0x00007ffff65c5f00 in ?? () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#13 0x00007ffff65cdd11 in g_signal_emit_valist () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#14 0x00007ffff65ce4b9 in g_signal_emit_by_name () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#15 0x0000000000427a57 in user_interface_set_crop (self=<optimised out>, crop_name=<optimised out>) at ui.c:2807
#16 0x00007ffff65b4620 in g_closure_invoke () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#17 0x00007ffff65c5f00 in ?? () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#18 0x00007ffff65cdd11 in g_signal_emit_valist () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#19 0x00007ffff65cdf92 in g_signal_emit () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#20 0x00007ffff78fc3c4 in ?? () from /usr/lib/x86_64-linux-gnu/libgtk-3.so.0
#21 0x00007ffff65b4620 in g_closure_invoke () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#22 0x00007ffff65c5544 in ?? () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#23 0x00007ffff65cdd11 in g_signal_emit_valist () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#24 0x00007ffff65cdf92 in g_signal_emit () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#25 0x000000000042a2c6 in crop_toolbutton_toggled_cb (widget=<optimised out>, self=<optimised out>) at ui.c:2880
#26 0x00007ffff65b48e7 in ?? () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#27 0x00007ffff65cd2df in g_signal_emit_valist () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#28 0x00007ffff65cdf92 in g_signal_emit () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#29 0x00007ffff65b4620 in g_closure_invoke () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#30 0x00007ffff65c5f00 in ?? () fro...

[TJ (tj)]

A better back-trace with symbols from libsqlite3-0

Program received signal SIGINT, Interrupt.
0x00007ffff546ec5d in write () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007ffff546ec5d in write () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007ffff6018991 in seekAndWrite (cnt=1024, pBuf=0xb18a48, offset=22789876, id=<optimised out>) at sqlite3.c:26012
#2 unixWrite (id=0x8884b0, pBuf=0xb18a48, amt=1024, offset=22789876) at sqlite3.c:26071
#3 0x00007ffff603cdff in sqlite3OsWrite (offset=22789876, amt=<optimised out>, pBuf=0xb18a48, id=<optimised out>)
    at sqlite3.c:14997
#4 pager_write (pPg=pPg@entry=0xb18e80) at sqlite3.c:42750
#5 0x00007ffff603d0b1 in sqlite3PagerWrite (pDbPage=0xb18e80) at sqlite3.c:42901
#6 0x00007ffff604ecea in freePage2 (pBt=pBt@entry=0x887df8, pMemPage=<optimised out>, iPage=iPage@entry=9350) at sqlite3.c:53488
#7 0x00007ffff604f157 in clearCell (pPage=pPage@entry=0x8991f8, pCell=<optimised out>) at sqlite3.c:53639
#8 0x00007ffff6053a51 in sqlite3BtreeInsert (pCur=<optimised out>, pKey=pKey@entry=0x0, nKey=<optimised out>, pData=0x2c0bf58,
    nData=<optimised out>, nZero=<optimised out>, appendBias=0, seekResult=0) at sqlite3.c:55208
#9 0x00007ffff607f617 in sqlite3VdbeExec (p=p@entry=0xcac4f8) at sqlite3.c:68076
#10 0x00007ffff6063341 in sqlite3Step (p=0xcac4f8) at sqlite3.c:62221
#11 sqlite3_step (pStmt=0xcac4f8) at sqlite3.c:62295
#12 sqlite3_step (pStmt=pStmt@entry=0xcac4f8) at sqlite3.c:62282
#13 0x000000000042fb02 in autosave_manager_update_page (self=<optimised out>, page=0x6b52d0) at autosave-manager.c:1423
#14 0x00007ffff65b4620 in g_closure_invoke () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#15 0x00007ffff65c5f00 in ?? () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#16 0x00007ffff65cdd11 in g_signal_emit_valist () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#17 0x00007ffff65ce4b9 in g_signal_emit_by_name () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#18 0x0000000000427a3b in user_interface_set_crop (self=<optimised out>, crop_name=<optimised out>) at ui.c:2801
#19 0x00007ffff65b4620 in g_closure_invoke () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#20 0x00007ffff65c5f00 in ?? () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#21 0x00007ffff65cdd11 in g_signal_emit_valist () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#22 0x00007ffff65cdf92 in g_signal_emit () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#23 0x00007ffff78fc3c4 in ?? () from /usr/lib/x86_64-linux-gnu/libgtk-3.so.0
#24 0x00007ffff65b4620 in g_closure_invoke () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#25 0x00007ffff65c5544 in ?? () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#26 0x00007ffff65cdd11 in g_signal_emit_valist () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#27 0x00007ffff65cdf92 in g_signal_emit () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#28 0x000000000042a2c6 in crop_toolbutton_toggled_cb (widget=<optimised out>, self=<optimised out>) at ui.c:2880
#29 0x00007ffff65b48e7 in ?? () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#30 0x00007ffff65cd2df in g_signal_emit_valist () from /usr/lib/x86_64-linux-gnu/l...

[TJ (tj)]

And another whilst waiting after having dragged the crop's bottom-right corner to a new location:

Program received signal SIGINT, Interrupt.
0x00007ffff546f31d in fsync () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007ffff546f31d in fsync () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007ffff602e46e in full_fsync (fd=<optimised out>, fullSync=<optimised out>, dataOnly=<optimised out>) at sqlite3.c:26201
#2 unixSync (id=0x8884b0, flags=<optimised out>) at sqlite3.c:26290
#3 0x00007ffff6054050 in sqlite3OsSync (flags=<optimised out>, id=<optimised out>) at sqlite3.c:15004
#4 syncJournal (newHdr=1, pPager=0x8882b8) at sqlite3.c:41288
#5 syncJournal (pPager=0x8882b8, newHdr=1) at sqlite3.c:41216
#6 0x00007ffff60557f5 in pagerStress (pPg=0xbea420, p=0x8882b8) at sqlite3.c:41572
#7 pagerStress (p=0x8882b8, pPg=0xbea420) at sqlite3.c:41529
#8 0x00007ffff600e7b7 in sqlite3PcacheFetch (pCache=0x8883c0, pgno=19429, createFlag=createFlag@entry=1,
    ppPage=ppPage@entry=0x7fffffffca98) at sqlite3.c:35302
#9 0x00007ffff603eabf in sqlite3PagerAcquire (pPager=0x8882b8, pgno=pgno@entry=19429, ppPage=ppPage@entry=0x7fffffffca98,
    noContent=noContent@entry=0) at sqlite3.c:42374
#10 0x00007ffff603ec78 in btreeGetPage (pBt=pBt@entry=0x887df8, pgno=pgno@entry=19429, ppPage=ppPage@entry=0x7fffffffcad8,
    noContent=noContent@entry=0) at sqlite3.c:49871
#11 0x00007ffff604b9d9 in getOverflowPage (pBt=pBt@entry=0x887df8, ovfl=ovfl@entry=19429, ppPage=ppPage@entry=0x7fffffffcb18,
    pPgnoNext=pPgnoNext@entry=0x7fffffffcb14) at sqlite3.c:52118
#12 0x00007ffff604f18c in clearCell (pPage=pPage@entry=0x8991f8, pCell=<optimised out>) at sqlite3.c:53620
#13 0x00007ffff6053a51 in sqlite3BtreeInsert (pCur=<optimised out>, pKey=pKey@entry=0x0, nKey=<optimised out>, pData=0x2c70358,
    nData=<optimised out>, nZero=<optimised out>, appendBias=0, seekResult=0) at sqlite3.c:55208
#14 0x00007ffff607f617 in sqlite3VdbeExec (p=p@entry=0xdeeee8) at sqlite3.c:68076
#15 0x00007ffff6063341 in sqlite3Step (p=0xdeeee8) at sqlite3.c:62221
#16 sqlite3_step (pStmt=0xdeeee8) at sqlite3.c:62295
#17 sqlite3_step (pStmt=pStmt@entry=0xdeeee8) at sqlite3.c:62282
#18 0x000000000042fb02 in autosave_manager_update_page (self=<optimised out>, page=0x6b52d0) at autosave-manager.c:1423
#19 0x00007ffff65b4620 in g_closure_invoke () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#20 0x00007ffff65c5f00 in ?? () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#21 0x00007ffff65cdd11 in g_signal_emit_valist () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#22 0x00007ffff65ce4b9 in g_signal_emit_by_name () from /usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0
#23 0x0000000000418259 in page_view_motion (self=0x6b5360, x=x@entry=307, y=<optimised out>) at page-view.c:3400
#24 0x00000000004125b7 in book_view_motion_cb (event=<optimised out>, widget=<optimised out>, self=0x86d190) at book-view.c:2003
#25 _book_view_motion_cb_gtk_widget_motion_notify_event (_sender=<optimised out>, event=0xa22410, self=0x86d190) at book-view.c:236
#26 0x00007ffff78af5ac in ?? () from /usr/lib/x86_64-linux-gnu/libgtk-3.so.0
#27 0x00007ffff65b48e7 in ?? () from /usr/lib/x86_64-linu...

[TJ (tj)]

The issue appears to be caused by the PageView.page_overlay_changed_cb() which emits the changed() signal which, as far as I can tell, calls AutosaveManager.on_page_changed() which calls AutosaveManager.update_page() every time the crop position is updated.

[Timo Kluck (tkluck)]

It appears that sqlite3 blobs are not really designed to handle large amounts of data like we're doing here. I just pushed a branch that saves the pixel data on the filesystem, instead. Please test!

[Philipp Morger (philipp-morger)]

Simple-Scan is unusable.... simple and useless :(

Can somebody please rip this frigging sqlite patch out of it - it is obviously not production ready.

[Tim Abell (tim-abell)]

@philipp, I agree, however I consider bug 897469 that this is I think supposed to solve to be even more evil, so I wouldn't like to see this feature dropped even thought it's clearly not up to scratch yet. (I'm just a user.)

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Robert Ancell (robert-ancell)]

Timo - you should propose that branch for merging into lp:simple-scan

[Launchpad Janitor (janitor)]

This bug was fixed in the package simple-scan - 3.9.90-0ubuntu1

---------------
simple-scan (3.9.90-0ubuntu1) saucy; urgency=low

  * New upstream release:
    - Only autosave after a timeout (LP: #1121169)
 -- Robert Ancell <email address hidden> Sun, 25 Aug 2013 15:41:57 +1200

[Joseph Nuzman (jnuzman)]

I can confirm that cropping is still unusable with 3.9.91, but works fine with lp:~tkluck/simple-scan/fix-cropping-slowness .

[Timo Kluck (tkluck)]

thanks for testing, Joseph! Can you also confirm that autosave works? You can simulate a crash by hitting Ctrl C in the console.

I'm interested to hear whether the necessary auto save database upgrade has gone well.

[Joseph Nuzman (jnuzman)]

Autosave overall seems to give similar results for 3.9.91 and the fix-cropping-slowness branch. In both cases, I scanned a single image and then terminated simple-scan with CTRL-C at the terminal. On restart, both versions found two copies of the scanned image and restored two indentical copies of the page.

Relevant output from the log:
[+0.04s] DEBUG: autosave-manager.vala:127: Found at least one autosave page, taking ownership
[+0.13s] DEBUG: autosave-manager.vala:572: Found a page that needs to be recovered
[+0.13s] DEBUG: autosave-manager.vala:588: Restoring a page of size 2549 x 3506
[+0.21s] DEBUG: autosave-manager.vala:624: Updating autosave to point to our new copy of the page
[+0.31s] DEBUG: autosave-manager.vala:572: Found a page that needs to be recovered
[+0.31s] DEBUG: autosave-manager.vala:588: Restoring a page of size 2549 x 3506
[+0.34s] DEBUG: autosave-manager.vala:624: Updating autosave to point to our new copy of the page
[+0.44s] DEBUG: autosave-manager.vala:393: Adding an autosave for a new page
[+0.54s] DEBUG: autosave-manager.vala:495: Updating the pixels in the autosave for a page
[+0.66s] DEBUG: autosave-manager.vala:393: Adding an autosave for a new page
[+0.76s] DEBUG: autosave-manager.vala:495: Updating the pixels in the autosave for a page
[+0.90s] DEBUG: autosave-manager.vala:445: Updating the autosave for a page

Only in the fix-cropping-slowness branch, I see the following lines upon clean exit:
[+33.02s] WARNING: autosave-manager.vala:209: Failed to delete autosave file
[+33.02s] WARNING: autosave-manager.vala:209: Failed to delete autosave file
[+33.02s] WARNING: autosave-manager.vala:209: Failed to delete autosave file

[Fiona Klute (fiona-klute)]

I still see this bug on Saucy, with simple-scan 3.10.0-0ubuntu1. After doing one low resolution scan ~/.cache/simple-scan/autosaves/autosaves.db reaches approximately 80MB, and the crop function is near-unusably slow. Selecting an area in that one page (moving the cropping area, adjusting borders, just a few seconds) resulted in no less than 9 (!) of these messages:
DEBUG: autosave-manager.vala:383: Updating the autosave for a page

Since I usually scan only one page, I'd be happy if I could just deactivate autosave altogether. Redoing the scan in the unlikely case of a crash would be much faster than waiting for all the autosaves to complete.

[vilbara (vilmantas-baranauskas)]

Can confirm this bug on 13.10 as well: Scanning and cropping a photo is insanely slow. The temp file is nearly 400MB in size and gets overwritten on each crop move.