Rapid Photo Downloader

Download performance in quantal

Asked by Sledge Sulaweyo

I use Rapid Photo Downloader for a while now but since i upgraded to quantal the performance is kind of terrible.

I import via a card reader and not directly from the camera. The fs in use the is FAT32 and the download speed was great with the last release but now it takes 15 minutes to import 50 NEFs (~20MB per file) which is just strange. There is as good as no IO or CPU load while importing.

I doubt that it's a bug so i wanted to ask if anybody else had this problem and maybe a solution.

Question information

Language:
English Edit question
Status:
Solved
For:
Rapid Photo Downloader Edit question
Assignee:
No assignee Edit question
Solved by:
Sledge Sulaweyo
Solved:
Last query:
Last reply:
Revision history for this message
Sledge Sulaweyo (sledge-sulaweyo) said : 		#1

The bug i linked is not the exact same behavior but close ... in my case RPD does not freeze but is just terrible slow on import.

Revision history for this message
Sledge Sulaweyo (sledge-sulaweyo) said : 		#2

Let me add some more info.
I tried the import from disk and to other devices to rule out problems with IO. The Log i attach here is an import of 3 Images from Disk (SSD, ext4) to ramdisk (tmpfs) so there should be no IO issue whatsoever. There is no error that i see, it's just slow. Neither CPU nor IO showed any strong usage during the whole import.
If i can do anything to help just give me a note - i have some idea of coding but did not dive into the source yet.

Sam Nov 3 10:00:02 CET 2012
sledge@hyperion:~$ rapid-photo-downloader --debug
[INFO/MainProcess] Rapid Photo Downloader 0.4.5
[INFO/MainProcess] Using pyexiv2 0.3.2
[INFO/MainProcess] Using exiv2 0.23.0
[INFO/MainProcess] Using exiftool 8.60
[INFO/MainProcess] Using hachoir 1.3.3
[INFO/MainProcess] Downloads that have occurred so far today: 3
[INFO/MainProcess] allocating a new mmap of length 4096
[DEBUG/MainProcess] created semlock with handle 139849963560960
[DEBUG/MainProcess] created semlock with handle 139849963556864
[DEBUG/MainProcess] created semlock with handle 139849963552768
[DEBUG/MainProcess] created semlock with handle 139849963548672
[DEBUG/MainProcess] created semlock with handle 139849963544576
[DEBUG/MainProcess] created semlock with handle 139849963540480
[DEBUG/MainProcess] created semlock with handle 139849963536384
[DEBUG/MainProcess] created semlock with handle 139849963532288
[DEBUG/MainProcess] _set_from_toolbar_state
[INFO/GetPreviewImage-1] child process calling self.run()
[DEBUG/MainProcess] Start of day is set to 3:0
[DEBUG/MainProcess] SubfolderFile PID: 6063
[INFO/MainProcess] Using manually specified path /home/sledge/Desktop
[INFO/MainProcess] # photo backup devices: 0; # video backup devices: 0
[INFO/SubfolderFile-2] child process calling self.run()
[DEBUG/SubfolderFile-2] Finished 0. Getting next task.
[DEBUG/MainProcess] created semlock with handle 139849963499520
[DEBUG/MainProcess] created semlock with handle 139849961549824
[DEBUG/MainProcess] created semlock with handle 139849938448384
[DEBUG/MainProcess] Queue._after_fork()
[DEBUG/MainProcess] created semlock with handle 139849938444288
[DEBUG/MainProcess] created semlock with handle 139849938440192
[DEBUG/MainProcess] created semlock with handle 139849938436096
[DEBUG/MainProcess] created semlock with handle 139849938432000
[DEBUG/MainProcess] created semlock with handle 139849938427904
[DEBUG/Scan-3] Queue._after_fork()
[INFO/Scan-3] child process calling self.run()
[DEBUG/MainProcess] TaskManager PID: 6064
[INFO/Scan-3] process shutting down
[DEBUG/Scan-3] running all "atexit" finalizers with priority >= 0
[DEBUG/Scan-3] running the remaining "atexit" finalizers
[INFO/Scan-3] process exiting with exitcode 0
[DEBUG/MainProcess] on_from_filechooser_button_selection_changed
[INFO/MainProcess] Found 3 photos
[INFO/MainProcess] Files total 51.3MB
[DEBUG/MainProcess] created semlock with handle 139849938423808
[DEBUG/MainProcess] created semlock with handle 139849938419712
[DEBUG/MainProcess] created semlock with handle 139849938415616
[DEBUG/MainProcess] Queue._after_fork()
[DEBUG/MainProcess] created semlock with handle 139849938411520
[DEBUG/MainProcess] created semlock with handle 139849938407424
[DEBUG/MainProcess] created semlock with handle 139849938403328
[DEBUG/MainProcess] created semlock with handle 139849938399232
[DEBUG/MainProcess] created semlock with handle 139849938395136
[DEBUG/MainProcess] TaskManager PID: 6066
[DEBUG/MainProcess] Turning on display of thumbnails
[DEBUG/GenerateThumbnails-4] Queue._after_fork()
[DEBUG/GenerateThumbnails-4] Queue._after_fork()
[INFO/GenerateThumbnails-4] child process calling self.run()
[DEBUG/GenerateThumbnails-4] Getting thumbnail for /home/sledge/Desktop/DCIM/100D7000/GBA_7986.NEF...
[DEBUG/GenerateThumbnails-4] file type is photo
[DEBUG/GenerateThumbnails-4] Read photo metadata...
[DEBUG/MainProcess] on_from_filechooser_button_selection_changed
[DEBUG/GenerateThumbnails-4] ...successfully read photo metadata
[DEBUG/GenerateThumbnails-4] Getting thumbnail data (160, 120)
[DEBUG/GenerateThumbnails-4] Ignoring embedded preview
[DEBUG/GenerateThumbnails-4] _get_thumbnail_data returned
[DEBUG/GenerateThumbnails-4] got td
[DEBUG/GenerateThumbnails-4] opened image
[DEBUG/GenerateThumbnails-4] downsizing
[DEBUG/GenerateThumbnails-4] Image size 4928x3264
[DEBUG/GenerateThumbnails-4] Box size 160x120
[DEBUG/GenerateThumbnails-4] quick resize 308x204
[DEBUG/MainProcess] on_from_filechooser_button_selection_changed
[DEBUG/GenerateThumbnails-4] did first thumbnail
[DEBUG/GenerateThumbnails-4] about to actually downsize using image.thumbnail
[DEBUG/GenerateThumbnails-4] it downsized
[DEBUG/GenerateThumbnails-4] downsized
[DEBUG/GenerateThumbnails-4] Image size 160x105
[DEBUG/GenerateThumbnails-4] Box size 100x100
[DEBUG/GenerateThumbnails-4] about to actually downsize using image.thumbnail
[DEBUG/GenerateThumbnails-4] it downsized
[DEBUG/GenerateThumbnails-4] ...got thumbnail for /home/sledge/Desktop/DCIM/100D7000/GBA_7986.NEF
[DEBUG/GenerateThumbnails-4] Getting thumbnail for /home/sledge/Desktop/DCIM/100D7000/GBA_7987.NEF...
[DEBUG/GenerateThumbnails-4] file type is photo
[DEBUG/GenerateThumbnails-4] Read photo metadata...
[DEBUG/GenerateThumbnails-4] ...successfully read photo metadata
[DEBUG/GenerateThumbnails-4] Getting thumbnail data (160, 120)
[DEBUG/GenerateThumbnails-4] Ignoring embedded preview
[DEBUG/GenerateThumbnails-4] _get_thumbnail_data returned
[DEBUG/GenerateThumbnails-4] got td
[DEBUG/GenerateThumbnails-4] opened image
[DEBUG/GenerateThumbnails-4] downsizing
[DEBUG/GenerateThumbnails-4] Image size 4928x3264
[DEBUG/GenerateThumbnails-4] Box size 160x120
[DEBUG/GenerateThumbnails-4] quick resize 308x204
[DEBUG/GenerateThumbnails-4] did first thumbnail
[DEBUG/GenerateThumbnails-4] about to actually downsize using image.thumbnail
[DEBUG/GenerateThumbnails-4] it downsized
[DEBUG/GenerateThumbnails-4] downsized
[DEBUG/GenerateThumbnails-4] Image size 160x105
[DEBUG/GenerateThumbnails-4] Box size 100x100
[DEBUG/GenerateThumbnails-4] about to actually downsize using image.thumbnail
[DEBUG/GenerateThumbnails-4] it downsized
[DEBUG/GenerateThumbnails-4] ...got thumbnail for /home/sledge/Desktop/DCIM/100D7000/GBA_7987.NEF
[DEBUG/GenerateThumbnails-4] Getting thumbnail for /home/sledge/Desktop/DCIM/100D7000/GBA_7988.NEF...
[DEBUG/GenerateThumbnails-4] file type is photo
[DEBUG/GenerateThumbnails-4] Read photo metadata...
[DEBUG/GenerateThumbnails-4] ...successfully read photo metadata
[DEBUG/GenerateThumbnails-4] Getting thumbnail data (160, 120)
[DEBUG/GenerateThumbnails-4] Ignoring embedded preview
[DEBUG/GenerateThumbnails-4] _get_thumbnail_data returned
[DEBUG/GenerateThumbnails-4] got td
[DEBUG/GenerateThumbnails-4] opened image
[DEBUG/GenerateThumbnails-4] downsizing
[DEBUG/GenerateThumbnails-4] Image size 4928x3264
[DEBUG/GenerateThumbnails-4] Box size 160x120
[DEBUG/GenerateThumbnails-4] quick resize 308x204
[DEBUG/GenerateThumbnails-4] did first thumbnail
[DEBUG/GenerateThumbnails-4] about to actually downsize using image.thumbnail
[DEBUG/GenerateThumbnails-4] it downsized
[DEBUG/GenerateThumbnails-4] downsized
[DEBUG/GenerateThumbnails-4] Image size 160x105
[DEBUG/GenerateThumbnails-4] Box size 100x100
[DEBUG/GenerateThumbnails-4] about to actually downsize using image.thumbnail
[DEBUG/GenerateThumbnails-4] it downsized
[DEBUG/GenerateThumbnails-4] ...got thumbnail for /home/sledge/Desktop/DCIM/100D7000/GBA_7988.NEF
[INFO/GenerateThumbnails-4] process shutting down
[DEBUG/GenerateThumbnails-4] running all "atexit" finalizers with priority >= 0
[DEBUG/GenerateThumbnails-4] running the remaining "atexit" finalizers
[INFO/GenerateThumbnails-4] process exiting with exitcode 0
[DEBUG/MainProcess] Download activated
[DEBUG/MainProcess] Prompting for Job Code
[DEBUG/MainProcess] Job Code entered
[DEBUG/MainProcess] Preference change detected: job_codes
[DEBUG/MainProcess] Job Code temp entered
[DEBUG/MainProcess] Photo download folder is valid: /tmp
[DEBUG/MainProcess] created semlock with handle 139849932169216
[DEBUG/MainProcess] created semlock with handle 139849932165120
[DEBUG/MainProcess] created semlock with handle 139849932161024
[DEBUG/MainProcess] Queue._after_fork()
[DEBUG/MainProcess] created semlock with handle 139849932156928
[DEBUG/MainProcess] created semlock with handle 139849932152832
[DEBUG/MainProcess] created semlock with handle 139849932148736
[DEBUG/MainProcess] created semlock with handle 139849932144640
[DEBUG/MainProcess] created semlock with handle 139849932140544
[DEBUG/MainProcess] TaskManager PID: 6074
[DEBUG/CopyFiles-5] Queue._after_fork()
[DEBUG/CopyFiles-5] Queue._after_fork()
[DEBUG/CopyFiles-5] Queue._after_fork()
[INFO/CopyFiles-5] child process calling self.run()
[DEBUG/MainProcess] Using temp dir /tmp/rpd-tmp-4c9vXF (photos)
[DEBUG/MainProcess] Download count: 1.
[INFO/CopyFiles-5] process shutting down
[DEBUG/CopyFiles-5] running all "atexit" finalizers with priority >= 0
[DEBUG/CopyFiles-5] running the remaining "atexit" finalizers
[INFO/CopyFiles-5] process exiting with exitcode 0
[DEBUG/MainProcess] Download count: 2.
[DEBUG/MainProcess] Download count: 3.
[DEBUG/SubfolderFile-2] Finish processing file: 1
[DEBUG/SubfolderFile-2] Finished 1. Getting next task.
[DEBUG/SubfolderFile-2] Finish processing file: 2
[DEBUG/SubfolderFile-2] Finished 2. Getting next task.
[DEBUG/SubfolderFile-2] Finish processing file: 3
[DEBUG/SubfolderFile-2] Finished 3. Getting next task.
[DEBUG/MainProcess] Purging temp directories
[DEBUG/MainProcess] Deleted directory /tmp/rpd-tmp-4c9vXF
[DEBUG/MainProcess] Download completed
[DEBUG/MainProcess] Preference change detected: downloads_today
[INFO/MainProcess] Terminating all processes...
[INFO/MainProcess] process shutting down
[DEBUG/MainProcess] running all "atexit" finalizers with priority >= 0
[INFO/MainProcess] calling terminate() for daemon GetPreviewImage-1
[INFO/MainProcess] calling terminate() for daemon SubfolderFile-2
[INFO/MainProcess] calling join() for process GetPreviewImage-1
[INFO/MainProcess] calling join() for process SubfolderFile-2
[DEBUG/MainProcess] running the remaining "atexit" finalizers
sledge@hyperion:~$ date
Sam Nov 3 10:01:37 CET 2012

Revision history for this message
Damon Lynch (dlynch3) said : 		#3

Hi, thanks for your further testing. If you have programming experience, especially when using multiple processes, you are always welcome to take a look at the code and try to figure what is going on. Obviously something changed between Ubuntu 12.04 and 12.10 that triggered the extreme slowdown.

Unfortunately due to critical academic committments I have been unable to dedicate any time to the problem, and will not be able to for several weeks at the earliest.

Revision history for this message
Sledge Sulaweyo (sledge-sulaweyo) said : 		#4

Hi Damon and thanks for your answer. I'll have a look at the code and maybe i find something. Time to get the dust off my python skills :)

Currently i'm downloading 400 shots - the download is at 96 after about 40 minutes and the GUI is frozen. As i started in debug mode i see it's still working so i let it run but as is it's unbearable.

Revision history for this message
Damon Lynch (dlynch3) said : 		#5

I suspect there is a problem occurring in the interprocess communication.
The code relies heavily on the Python multiprocessing module. From memory,
most interprocess communication in the program occurs using pipes, but
there might be one or two queues in there as well. I have no idea why it
would suddenly perform badly after working without apparent problems in
previous Ubuntu releases.

The problem may lie elsewhere, however. Perhaps some profiling might detect
the root cause of the problem.

Revision history for this message
Damon Lynch (dlynch3) said : 		#6

Status accidentally set to "answered" when replying via email

Revision history for this message
Sledge Sulaweyo (sledge-sulaweyo) said : 		#7

Hi Damon,

thank you very much - 0.4.6.beta1 solved this issue!
So closed for good in my book :)