Bug 275813 - Digikam hangs on startup (splash screen: reading database)
Summary: Digikam hangs on startup (splash screen: reading database)
Status: RESOLVED FIXED
Alias: None
Product: digikam
Classification: Applications
Component: ProgressManager-Splashscreen (show other bugs)
Version: 1.9.0
Platform: Fedora RPMs Linux
: NOR crash
Target Milestone: ---
Assignee: Digikam Developers
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2011-06-16 13:10 UTC by Michael Körber
Modified: 2022-02-05 12:59 UTC (History)
1 user (show)

See Also:
Latest Commit:
Version Fixed In: 2.0.0
Sentry Crash Report:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Michael Körber 2011-06-16 13:10:29 UTC
Version:           1.9.0 (using KDE 4.6.3) 
OS:                Linux

Although the option 'Scan for new items on startup' is deactivated, digikam traverses the whole storage in /home/username/Bilder where in /home/username/Bilder/net_bilder a cifs is mounted. For each directory digikam calls inotify_add_watch (not included in the following strace).

Each time the cifs is mounted digikam hangs on reading database with the following strace. This behaviour is reproducible.

The image storage is located on a raid storage 1.5TB of size. The image storage's size is 77 GB with 195,033 files in 9,668 folders. All drives have more than 80GB of free space. The sqlite3 databse is located in /home/username/Bilder.

/home/username/Bilder
  + net_bilder (cifs mount point)
  + digikam4.db
  + thumbnails-digikam.db

'strace digikam' produces the following output:
[...]thousands of other lines[...]
stat64("/home/username/Bilder/net_bilder/cifs_mounted_here/pic13.jpg", {st_mode=S_IFREG|0755, st_size=65866, ...}) = 0
stat64("/home/username/Bilder/net_bilder/cifs_mounted_here/pic11.jpg", {st_mode=S_IFREG|0755, st_size=52490, ...}) = 0
stat64("/home/username/Bilder/net_bilder/cifs_mounted_here/pic14.jpg", {st_mode=S_IFREG|0755, st_size=61893, ...}) = 0
stat64("/home/username/Bilder/net_bilder/cifs_mounted_here/pic16.jpg", {st_mode=S_IFREG|0755, st_size=61375, ...}) = 0
stat64("/home/username/Bilder/net_bilder/cifs_mounted_here/pic06.jpg", {st_mode=S_IFREG|0755, st_size=44437, ...}) = 0
stat64("/home/username/Bilder/net_bilder/cifs_mounted_here/pic07.jpg", {st_mode=S_IFREG|0755, st_size=59157, ...}) = 0
stat64("/home/username/Bilder/net_bilder/cifs_mounted_here/pic09.jpg", {st_mode=S_IFREG|0755, st_size=72442, ...}) = 0
stat64("/home/username/Bilder/net_bilder/cifs_mounted_here/pic18.jpg", {st_mode=S_IFREG|0755, st_size=99327, ...}) = 0
stat64("/home/username/Bilder/net_bilder/cifs_mounted_here/pic10.jpg", {st_mode=S_IFREG|0755, st_size=66041, ...}) = 0
stat64("/home/username/Bilder/net_bilder/cifs_mounted_here/pic01.jpg", {st_mode=S_IFREG|0755, st_size=81829, ...}) = 0
stat64("/home/username/Bilder/net_bilder/cifs_mounted_here/pic15.jpg", {st_mode=S_IFREG|0755, st_size=64597, ...}) = 0
stat64("/home/username/Bilder/net_bilder/cifs_mounted_here/pic08.jpg", {st_mode=S_IFREG|0755, st_size=64902, ...}) = 0
stat64("/home/username/Bilder/net_bilder/cifs_mounted_here/.picasa.ini", {st_mode=S_IFREG|0755, st_size=320, ...}) = 0
stat64("/home/username/Bilder/net_bilder/cifs_mounted_here/pic03.jpg", {st_mode=S_IFREG|0755, st_size=85237, ...}) = 0
stat64("/home/username/Bilder/net_bilder/cifs_mounted_here/pic05.jpg", {st_mode=S_IFREG|0755, st_size=54018, ...}) = 0
getdents64(52, /* 0 entries */, 32768)  = 0
close(52)                               = 0
stat64("/home/username/Bilder/net_bilder/cifs_mounted_here/pic12.jpg", {st_mode=S_IFREG|0755, st_size=66438, ...}) = 0
open("/etc/mtab", O_RDONLY)             = 52
fstat64(52, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb788b000
read(52, "rootfs / rootfs rw 0 0\n/proc /pr"..., 1024) = 1024
read(52, "ct 0 0\ncgroup /sys/fs/cgroup/mem"..., 1024) = 1024
read(52, "latime,mode=755 0 0\n/dev/sda5 /b"..., 1024) = 1024
read(52, "6384,wsize=57344,actimeo=1 0 0\n/"..., 1024) = 274
read(52, "", 1024)                      = 0
close(52)                               = 0
munmap(0xb788b000, 4096)                = 0
lstat64("/home", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat64("/home/username", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
lstat64("/home/username/Bilder", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat64("/home/username/Bilder/net_bilder", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat64("/home/username/Bilder/net_bilder/sway", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
lstat64("/home/username/Bilder/net_bilder/cifs_mounted_here", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
inotify_add_watch(21, "/home/username/Bilder/net_bilder/cifs_mounted_here", IN_MODIFY|IN_ATTRIB|IN_MOVED_FROM|IN_MOVED_TO|IN_CREATE|IN_DELETE|IN_DELETE_SELF|IN_MOVE_SELF|IN_DONT_FOLLOW) = -1 ENOSPC (No space left on device)
inotify_add_watch(21, "/home/username/Bilder/net_bilder/cifs_mounted_here", IN_MODIFY|IN_ATTRIB|IN_MOVED_FROM|IN_MOVED_TO|IN_CREATE|IN_DELETE|IN_DELETE_SELF|IN_MOVE_SELF|IN_DONT_FOLLOW) = -1 ENOSPC (No space left on device)
select(21, [20], NULL, NULL, {0, 0})    = 0 (Timeout)
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65) = ? ERESTARTSYS (To be restarted)
--- {si_signo=SIGWINCH, si_code=SI_KERNEL} (Window changed) ---
write(20, "A\0\1\0i\5\2\0007\0/home/username/Bilder/"..., 65

'strace -c digikam' results:
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 84.73   15.701426          68    230393      1146 stat64
  6.13    1.136214          55     20839           getdents64
  3.73    0.690976          70      9828           statfs
  2.76    0.511118           4    127309       716 lstat64
  1.37    0.253446           3     93394     30387 read
  0.42    0.078354           4     22045           poll
  0.27    0.049869           2     21931       601 open
  0.12    0.023062           2     11408      3339 inotify_add_watch
  0.09    0.017135           1     21391           close
  0.07    0.013512           1     10901           writev
  0.07    0.012060           1     22055     12391 access
  0.06    0.011168           1     10897           munmap
  0.04    0.007833           1     11716           mmap2
  0.03    0.005869           0     12458           fstat64
  0.02    0.003290           0     14024           clock_gettime
  0.02    0.003285           2      2079       967 readlink
  0.01    0.002418           1      4628           write
  0.01    0.002267         108        21         2 connect
  0.01    0.001767           0      3921           select
  0.01    0.001581           6       245        16 futex
  0.01    0.000968           2       458           sendmsg
  0.00    0.000845           0      8069           inotify_rm_watch
  0.00    0.000400           0      1250           fcntl64
  0.00    0.000353           0       739       351 recvmsg
  0.00    0.000271          19        14           rename
  0.00    0.000188           0       447           gettimeofday
  0.00    0.000178           0       583           brk
  0.00    0.000135          27         5           getdents
  0.00    0.000114           1       103           getcwd
  0.00    0.000039           1        60           uname
  0.00    0.000034           0       437           _llseek
  0.00    0.000014           0        45         1 kill
  0.00    0.000000           0        14           link
  0.00    0.000000           0        78        13 unlink
  0.00    0.000000           0         1           execve
  0.00    0.000000           0       424           time
  0.00    0.000000           0         1           utime
  0.00    0.000000           0         1         1 mkdir
  0.00    0.000000           0         5           pipe
  0.00    0.000000           0       119        34 ioctl
  0.00    0.000000           0         2           umask
  0.00    0.000000           0         1           ftruncate
  0.00    0.000000           0        42           fchmod
  0.00    0.000000           0         2           fstatfs
  0.00    0.000000           0        54           clone
  0.00    0.000000           0        42           mprotect
  0.00    0.000000           0        12           fdatasync
  0.00    0.000000           0         1           sched_getparam
  0.00    0.000000           0         1           sched_getscheduler
  0.00    0.000000           0         4           sched_get_priority_max
  0.00    0.000000           0         3           sched_get_priority_min
  0.00    0.000000           0        39           rt_sigaction
  0.00    0.000000           0         2           rt_sigprocmask
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         5           ftruncate64
  0.00    0.000000           0        62           getuid32
  0.00    0.000000           0         9           getgid32
  0.00    0.000000           0        12           geteuid32
  0.00    0.000000           0         6           getegid32
  0.00    0.000000           0        14           fchown32
  0.00    0.000000           0         1           getresuid32
  0.00    0.000000           0         1           getresgid32
  0.00    0.000000           0        12           madvise
  0.00    0.000000           0         1           sched_getaffinity
  0.00    0.000000           0         1           set_thread_area
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         4           clock_getres
  0.00    0.000000           0         1           statfs64
  0.00    0.000000           0         1           inotify_init
  0.00    0.000000           0        11           ppoll
  0.00    0.000000           0         1           set_robust_list
  0.00    0.000000           0         1           timerfd_create
  0.00    0.000000           0         6           pipe2
  0.00    0.000000           0         5           inotify_init1
  0.00    0.000000           0        36           socket
  0.00    0.000000           0        15           bind
  0.00    0.000000           0        14           listen
  0.00    0.000000           0        13           accept
  0.00    0.000000           0        27           getsockname
  0.00    0.000000           0        20           getpeername
  0.00    0.000000           0         6           socketpair
  0.00    0.000000           0        32         2 send
  0.00    0.000000           0         3           recv
  0.00    0.000000           0        17           setsockopt
  0.00    0.000000           0        16           getsockopt
  0.00    0.000000           0         2           shmat
  0.00    0.000000           0         1           shmdt
  0.00    0.000000           0         2           shmget
  0.00    0.000000           0         2           shmctl
------ ----------- ----------- --------- --------- ----------------
100.00   18.530189                664903     49967 total

Entry in fstab is this:
//192.168.1.5/Public/Bilder /home/username/Bilder/net_bilder   cifs auto,rw,uid=500,gid=500,credentials=/home/username/.smbcredentials 0 0

In some rare cases digikam starts in about 50 Minutes. In the majority of cases digikam hangs as described.

Here more information concerning my laptop.
http://www.smolts.org/client/show_all/pub_8d14167e-db4d-40c9-99e4-ac63418ef8e3

I'm not using the KDE-Desktop. My desktop environment is Gnome3 with the gnome-shell.

The current Kernel is 2.6.38.7-30.

Reproducible: Always

Steps to Reproduce:
Start digikam with lagre image storage mounted by cifs.

Actual Results:  
It hangs showing the splash screen with reading database message on it.

Expected Results:  
Simply startup.

Cause of digikam is unusable the severity will be set to crash.
Comment 1 Marcel Wiesweg 2011-06-16 13:18:53 UTC
- is the relevant CIFS collection added as a network collection or as a normal collection in setup? Is the directory sometimes not mounted?
- is the command 
find /home/username/Bilder/net_bilder
considerably faster than digikam's scanning?
Comment 2 Michael Körber 2011-06-16 13:41:28 UTC
The relevant cifs-collection is added as a network collection in setup.
The find /home/username/Bilder/net_bilder takes 00:02:36.69.
Yes it is considerably faster.
Even over night digikam is unable to start.
Comment 3 Michael Körber 2011-06-16 13:45:59 UTC
I tried starting digikam without the cifs being mounted. Digikam starts immediately.
Comment 4 Michael Körber 2011-06-16 14:04:15 UTC
Perhaps this cli output is helpful.

KGlobal::locale::Warning your global KLocale is being recreated with a valid main component instead of a fake component, this usually means you tried to call i18n related functions before your main component was created. You should not do that since it most likely will not work 
QSqlDatabasePrivate::removeDatabase: connection 'ConnectionTest' is still in use, all queries will cease to work.
Time elapsed: 61 ms
Model: Time elapsed: 0 ms
TextureColorizer::setSeaFileLandFile: Time elapsed: 9 ms
Time elapsed: 4 ms
Model: Time elapsed: 0 ms
kbuildsycoca4 running...
KGlobal::locale::Warning your global KLocale is being recreated with a valid main component instead of a fake component, this usually means you tried to call i18n related functions before your main component was created. You should not do that since it most likely will not work 
QSqlDatabasePrivate::removeDatabase: connection 'digikamDatabase-158723464' is still in use, all queries will cease to work.
klauncher(1835)/kio (KLauncher): SlavePool: No communication with slave. 

klauncher(1835)/kio (KLauncher): SlavePool: No communication with slave. 

klauncher(1835)/kio (KLauncher): SlavePool: No communication with slave. 

klauncher(1835)/kio (KLauncher): SlavePool: No communication with slave. 

QSocketNotifier: Invalid socket 13 and type 'Read', disabling...
klauncher(1835)/kio (KLauncher): SlavePool: No communication with slave. 

klauncher(1835)/kio (KLauncher): SlavePool: No communication with slave. 

klauncher(1835)/kio (KLauncher): SlavePool: No communication with slave. 

klauncher(1835)/kio (KLauncher): SlavePool: No communication with slave. 

klauncher(1835)/kio (KLauncher): SlavePool: No communication with slave.
Comment 5 Michael Körber 2011-06-23 09:14:06 UTC
I switched to another Linux distribution. The reported Bug occured with Fedora 15. Now I'm using Ubuntu 11.04. Everything works fine and digikam starts within 4 minutes. In consideration of my collection's size (see above) this is acceptable for me.
Comment 6 Marcel Wiesweg 2011-06-23 12:40:42 UTC
It is still slower than a local collection, and needs improvement, but as you see the major issue was due to CIFS implementation probably in connection with adding KDirWatches.