Bug 172269

Summary: Digikam hangs for around 20-60 seconds when starting
Product: [Applications] digikam Reporter: Antonio E. <aironmail>
Component: Database-ScanAssignee: Digikam Developers <digikam-bugs-null>
Status: RESOLVED FIXED    
Severity: crash CC: arnd.baecker, marcel.wiesweg
Priority: NOR    
Version: 0.10.0   
Target Milestone: ---   
Platform: Compiled Sources   
OS: Unspecified   
Latest Commit: Version Fixed In: 0.10.0
Sentry Crash Report:

Description Antonio E. 2008-10-06 14:11:07 UTC
Version:           0.10.0-beta4 svn (using Devel)
Installed from:    Compiled sources

This is something that I've never noticed with older digikam series (0.9.x, 0.8.x, ...).

Since I started to use the 0.10.x from svn, I'm experimenting a very large starting time for digikam.

If I start the application from konsole, almost instantly, I get the splashscreen.

It goes up to "Scanning images in individual albums", and it hangs there for around 20-60 seconds, it depends on the day, and if I have run the application previosly (probably libraries cached on memory).

What I've noticed, is that the first log messages that appear in the konsole after digikam continues starting normally are these:

setting xine verbosity to 0
Uing Xine version 1.1.15
isEmpty
outputPlugin:    alsa
outputPlugin:    oss
outputPlugin:    arts
outputPlugin:    esd
outputPlugin:    file
outputPlugin:    none
10001 "Esound (ESD)"  "esd"
10000 "aRts"  "arts"
Phonon::Xine::Backend(0x83e3728)  2
xcb_connect 0x868b558
...

So, apparently, it's like if it hangs while it gets access to the output plugin for sound. Maybe it is not related or mayby it is, because digikam continues loading exactly when it prints those messages.

My image collection can be around 7 to 8k images, but it's more or less of the same size than the last time that I used the 0.9.x series.

Any idea?

Thanks in advance.

Antonio E.
Comment 1 caulier.gilles 2008-10-06 14:25:54 UTC
How digiKam is compiled ?

Are you enable marble component for geolocation ?

Do you start digiKam under a KDE4 session or KDE3 ?

You said that it sound like a sound interface problem. If yes, only phonon component is used in digiKam, to display video.sound preview. Can you test with another KDE4 application which depand of phonon to check if problem is reproductible ?

Gilles Caulier
Comment 2 Antonio E. 2008-10-06 14:38:45 UTC
Hi.

Digikam is compiled using an ebuild that compiles the svn trunk. It has the normal compiling options than for the rest of apps in my system.

I'm using gcc 4.1.2 with the CFLAGS="-O2 -march=pentium4 -fomit-frame-pointer -pipe"

I'm enabling all options from the configure except the lensfun support, so yes, the marble component is set as a compiling option and working fine.

I start digikam from KDE4.

Then, about the sound interface problem. I have not such kind of delays on Phonon. For example, the dragon player starts almost instantaneusly, printing exactly the same messages than digikam about the sound. So, perhaps it's not related.

The thing is that, I start digikam. I see the splashscreen and nothing on the console. It hangs for the time that I said on the "Scanning images in individual albums", and only after it finally prints the sound messages on the console it continues with the starting process.

I don't know what can be. The sound interface, the sqlite, ... I haven't compared the starting time with other people, so I don't know if is normal or not, but definitely, on my system much slower than the previous series.

Then after starting it works great, so it's just something with the starting process.

Thank you.

Antonio E.
Comment 3 Andi Clemens 2008-10-06 15:07:35 UTC
I can confirm this, but for me it doesn't hang, it is just scanning the images that long. If I use the same amount of image with digikam 0.9x, it scans my collection very fast on startup, but digiKam 0.10 always seems to scan all directories from the beginning, as if it doesn't know all those images.
The only solution for me is to turn off "scan on startup". But I really don't understand what digikam 0.10 is doing there, it was so much faster with 0.9x.

Andi
Comment 4 Antonio E. 2008-10-06 15:14:25 UTC
Well. True, perhaps I didn't use the right word for "hang", but it's exactly what Andi has said: apparently in a big pause while scaning the albums, doing I don't know what else than the 0.9.x series.

There's in addition a little extra annoying thing, and is that if while the splashscreen is there and digikam loading for that time, if I click on the splashscreen, it gets closed. So with no hint for the user to know that the application is still running, until it opens after some time.
Comment 5 caulier.gilles 2008-10-06 15:20:40 UTC
Andy, Antonio,

Sound like an old problem fixed in the pass by Marcel about a database lock.

Antonio, to confirm this, please got to Setup/mics config panel, and disable scan at startup. restart digiKam and look if problem diseapear...

Note : in the pass i have already reported this problem. but since a long time now this problem do not exist on my computer. I have a huge collection of image here (JPEG, TIFF, RAW, PNG, etc...)

Antonio, the database backend is sqlite. We use Qt4::Sql interafce thure the sqlite plugin for Qt4. We don't have any control here of sqlite version used with digiKam. THIS IS NOT the case with KDE3 version where i have embeded sqlite code in digiKam using a fully tested version...

Sqlite team break sometime code in backend (yes, it's a shame (:=)))). Amarok team have the same problem than digiKam. 

Please can you check which sqlite version is compiled into your Qt4 plugin ? (just to be sure)

To Marcel : i thinking to do something like KDE3 in KDE4: embeding sqlite code into a dedicated Qt4 plugin to have a fine control of database backend used and prevent future problem. Of course, we need to check if problem come from sqlite of digiKam DB interafce.

To Arnd : do you remember which sqlite version is depreciate exactly (following investiguations from KDE3 branch)

Gilles Caulier
Comment 6 Andi Clemens 2008-10-06 15:47:08 UTC
Gilles,

as you know I'm always using trunk, it is not solved here. In general scanning takes much longer than 0.9x series. If I hit "scan for new images", it takes like 1 second in digikam 0.9.5, but in 0.10 it rescans everything, so it takes approximately 2 minutes.

Andi
Comment 7 Antonio E. 2008-10-06 16:06:56 UTC
Thanks for the answer, Gilles.

I've unchecked the option that you said (disable scan at startup), and yes, now
digikam starts as was usual with the 0.9.x series. So it seems that you're
right with the diagnostic.

On my system, I have two instances of sqlite, with two binaries:
sqlite (2.8.16)
sqlite3 (3.5.9)

The qt plugin for sqlite is linked with the 3.5.9 version.

$ ldd /usr/lib/qt4/plugins/sqldrivers/libqsqlite.so
        linux-gate.so.1 =>  (0xffffe000)
        libsqlite3.so.0 => /usr/lib/libsqlite3.so.0 (0xb7eec000)
        libQtSql.so.4 => /usr/lib/qt4/libQtSql.so.4 (0xb7eb2000)
        libQtCore.so.4 => /usr/lib/qt4/libQtCore.so.4 (0xb7c97000)
        libz.so.1 => /lib/libz.so.1 (0xb7c83000)
        librt.so.1 => /lib/librt.so.1 (0xb7c79000)
        libpthread.so.0 => /lib/libpthread.so.0 (0xb7c62000)
        libdl.so.2 => /lib/libdl.so.2 (0xb7c5e000)
        libstdc++.so.6 => /usr/lib/gcc/i686-pc-linux-gnu/4.1.2/libstdc++.so.6
(0xb7b81000)
        libm.so.6 => /lib/libm.so.6 (0xb7b5b000)
        libgcc_s.so.1 => /usr/lib/gcc/i686-pc-linux-gnu/4.1.2/libgcc_s.so.1
(0xb7b51000)
        libc.so.6 => /lib/libc.so.6 (0xb7a20000)
        /lib/ld-linux.so.2 (0xb7f8e000)

Just in case, I'm using qt-4.4.1.


So, well, disabling the option I return to "normal" starting times.

But, it's what Andi says, on 0.9.x we had the option set, and it didn't spend
so much time.

I can try to upload my sqlite to a newer version, lets say 3.6.2, and try to
set back the option to scan the albums and see how it behaves, in case that you
think that is a good test.

Please, do not doubt to tell me any kind of steps that I can do to try to help
on this.

Thanks.

Antonio E.
Comment 8 Andi Clemens 2008-10-06 16:10:03 UTC
I'm using sqlite3-3.6.3, not faster here...
Comment 9 Antonio E. 2008-10-06 16:22:09 UTC
I've uploaded sqlite to 3.6.2 and set the option scan the albums on the start. It didn't help: it took 78 seconds to start.
Comment 10 Arnd Baecker 2008-10-06 17:33:11 UTC
Gilles, 

sqlite 3.5.8. was the one causing problems, see
http://bugs.kde.org/show_bug.cgi?id=160966
So this (together with Andis comment) suggests, that it might be something different ...

Best, Arnd
Comment 11 caulier.gilles 2008-10-06 18:34:43 UTC
Arnd,

Yes, it's a scan problem at startup, not a sqlite lock... i think.

To be more clear, we cannot compare KDE3 with KDE4 implementation: Marcel as re-written scanning code. In KDE3 this class is used :

http://websvn.kde.org/branches/extragear/kde3/graphics/digikam/digikam/scanlib.h?revision=788153&view=markup

...and have been removed by this code :

http://websvn.kde.org/trunk/extragear/graphics/digikam/digikam/scancontroller.h?revision=861865&view=markup

Which is slitly different. scancontroller for ex, can be multithreaded against scanlib no...

But of course, the same behaviour at start up must be the same. 

It look like scancontroler check, parse, and records all DB items each time and try to find new items, where scanlib only check and records new items in DB as well. 

But i can be wrong here. I don't have checked Marcel code...

Gilles
Comment 12 Marcel Wiesweg 2008-10-09 15:57:40 UTC
I have added debug messages to SVN which print out the time spent in all parts of collection scanning. So Andi (or Antonio), if you could please test and post the messages from console here, so that we know where the scanning code is spending its time.
Comment 13 Antonio E. 2008-10-09 21:36:24 UTC
I've just compiled the latest trunk. But, Marcel I can't find any message about the time spent at any task. Do I have to pass any extra parameter to compile it or they should just be there as the rest of log messages that can be read by default (I assumed that from your message)? But again this time, the first message appear in the console after leaving the "scanning images in individual albums", nothing before.
Comment 14 Andi Clemens 2008-10-09 21:55:54 UTC
Antonio, you need to compile digiKam with full debugging:

cmake -DCMAKE_BUILD_TYPE=debugfull

Marcel,
I've measured the time but I guess this will be no help, it spends nearly the same amount of time in every folder. I guess the problem seems to be that it scans every existing folder from the beginning, in digikam 0.9.x it seems only to scan folders that have changed.

Andi
Comment 15 Marcel Wiesweg 2008-10-10 16:02:01 UTC
In 0.9 the algorithm was:
Stat file names in dir, get file names from db, compare, scan new files.

In 0.10 it is:
Stat directory info (name + modification date),
get name+modification date from db, compare, scan new or changed files.

For an album with 500 images, my timing log is as follows:
Digikam::CollectionScanner::scanAlbum: Scanning album "/media/fotos/Mailand 2008"
 Digikam::CollectionScanner::scanAlbum: Checks and creating album 1
 Digikam::CollectionScanner::scanAlbum: List entries from database 36
 Digikam::CollectionScanner::scanAlbum: Arranged in hashes 1
 Digikam::CollectionScanner::scanAlbum: Stat'ing directory 1398
 Digikam::CollectionScanner::scanAlbum: Checked individual files 7

As you see, the only significant time spent is for stat'ing, which is for us one line of code:
    const QFileInfoList list = dir.entryInfoList(d->nameFilters, QDir::AllDirs | QDir::Files  | QDir::NoDotAndDotDot /*not CaseSensitive*/);

Command line "dir" can stat this directory in 200ms (<70ms with hot caches), so Qt is doing stuff here that takes too much time.
Before I get to optimizing here however, I would like to know if you have actually the same problem.
Comment 16 Andi Clemens 2008-10-10 16:30:11 UTC
Hi,

I just tested it with a folder that has nearly 6300 images in it:

digikam(11515) Digikam::CollectionScanner::scanAlbum: Checks and creatin album 1
digikam(11515) Digikam::CollectionScanner::scanAlbum: List entries from database 92
digikam(11515) Digikam::CollectionScanner::scanAlbum: Arranged in hashes 5
digikam(11515) Digikam::CollectionScanner::scanAlbum: Stat'ing directory 11372
digikam(11515) Digikam::CollectionScanner::scanAlbum: Checked individual files 64
digikam(11515) Digikam::CollectionScanner::scanAlbum: Descending to subalbum

So yes stating takes a long time, from command line 'stat' takes 4ms and 'dir' takes '45ms'.

Andi
Comment 17 Andi Clemens 2008-10-10 16:33:27 UTC
One little note:

It seems that digiKam 0.9.x series scans only the root folders of my collection (but maybe I'm wrong, it is too fast to see what's exactly going on there), but 0.10 scans every single folder.

So having a structure like this:

2001
|- bla1
|- bla2
   |- blablub1
2002
|- bla3

it seems that 0.9.x is scanning 2001 and 2002, whereas 0.10 scans 2001, bla1, bla2, etc....

Andi 
Comment 18 Andi Clemens 2008-10-10 16:36:18 UTC
The problem with my collection might be that I have a lot of small folders. I photograph a lot (daily) and so I have a folder for nearly every day. This is why scanning on startup slows down digiKam, but again in 0.9.x it is much much faster, so fast that I can leave "scan on startup" turned on.
Comment 19 Marcel Wiesweg 2008-10-10 17:59:40 UTC
Update: I can confirm that this is a problem with entryInfoList; removing the file name filter makes it faster by a factor of 20. It seems that the name filter that we use - containing a quite large number of file suffixes - is applied with a QRegExp for each suffix, for each file. We can do that faster without prefiltering.
Comment 20 Marcel Wiesweg 2008-10-11 17:17:35 UTC
As confirmed by Andi, the problem is fixed by the commit listed below.

Author: mwiesweg <mwiesweg@283d02a7-25f6-0310-bc7c-ecb5cbfe19da>
Date:   Sat Oct 11 13:55:40 2008 +0000

    Do not use the file name filter that comes with QDir.entryInfoList, which
    is very slow for larger file counts and filtered suffixes.
    Just get all files and use plain simple suffix filtering from a QSet.

    Speeds up complete collection scan by approximately factor 20.

    git-svn-id: https://svn.kde.org/home/kde/trunk/extragear/graphics/digikam@869972 283d02a7-25f6-0310-bc7c-ecb5cbfe19da
Comment 21 Antonio E. 2008-10-12 03:25:58 UTC
I confirm that behaviour now it's very good, I've just tested the latest trunk. Wow, what a change! It has improved dramatically the starting time. Well seen Marcel.

Thank you :).