From: phantomjinx <p.g...@ph...> - 2010-07-07 21:35:24
|
Hi people, Second beta of gtkpod with most of the fixes suggested since the weekend included. http://www.phantomjinx.co.uk/stuff/gtkpod-1.0.0-beta2.tar.gz Happy testing. Cheers PGR (a.k.a. phantomjinx) |
From: Leandro L. <lu...@ll...> - 2010-07-07 23:08:28
|
phantomjinx, el 7 de julio a las 22:35 me escribiste: > Hi people, > > Second beta of gtkpod with most of the fixes suggested since the weekend included. > > http://www.phantomjinx.co.uk/stuff/gtkpod-1.0.0-beta2.tar.gz > > Happy testing. Any comments on the problem I've reported in the announcement of beta 1? Thanks! -- Leandro Lucarella (AKA luca) http://llucax.com.ar/ ---------------------------------------------------------------------- GPG Key: 5F5A8D05 (F8CD F9A7 BF00 5431 4145 104C 949E BFB6 5F5A 8D05) ---------------------------------------------------------------------- Relax. I'll need some information first. Just the basic facts. Can you show me where it hurts? |
From: Javier K. <jk...@gm...> - 2010-07-11 19:46:14
|
On Sun, Jul 11, 2010 at 20:00, Leandro Lucarella <lu...@ll...> wrote: > phantomjinx, el 11 de julio a las 17:58 me escribiste: > > On 10/07/10 04:21, Leandro Lucarella wrote: > > > Leandro Lucarella, el 9 de julio a las 20:53 me escribiste: > > > > > >> pm_selection_changed_cb() and st_selection_changed_cb() are both > taking > > >> an eternity, and both apparently because of the TreeView manipulation. > > >> Besides that being too slow, I don't know why those callbacks are > called > > >> so many times, since only one click on the iPod playlist triggered all > > >> that callbacks (which makes things even worse). > > >> > > > I did a run using valgrind's callgrind and those 2 functions are taking > > > ~87% of the work. Here is the callgrind log file, you can explore it > > > with kcachegrind to see if you find anything particularly strange: > > > http://www.llucax.com.ar/tmp/callgrind.out.16685.bz2 > > > (~450KB download, ~2.5MB uncompressed) > > > > > > The logged session is not complete until all the data was shown, just > > > a couple of calls to pm_selection_changed_cb() and > > > st_selection_changed_cb(), it took several hours to reach this point :) > > > > > > Here is the log (just using DEBUG_TIMING, without my extra printf()s): > > > pm_selection_changed_cb enter: 526.562090 sec > > > pm_selection_changed_cb exit: 3541.055112 sec > > > st_selection_changed_cb enter (inst: 0): 3578.167885 sec > > > st_selection_changed_cb exit: 438.241159 sec > > > st_selection_changed_cb enter (inst: 1): 438.241632 sec > > > st_selection_changed_cb exit: 852.802046 sec > > > st_selection_changed_cb enter (inst: 1): 859.227562 sec > > > [killed] > > > > > > > Thanks for your efforts so far. > > Is the least I can do to thank you for gtkpod =) > > > I think it might be time to take pm_selection_changed_cb to pieces as my > > suspicion is the following: > > > > - Change selection to ipod master playlist causes pm_selection_changed_cb > > - st_init called and tends to call st_selection_changed_cb for each > > filter tab that is re-inited > > > > I would say that the performance bottleneck is due to st_init being > > called and st_selection_changed_cb being fired too many times > > > > So, can you try commenting sections of the code out in > > pm_selection_changed_cb and see if you can isolate exactly which part of > > the code is taking so long? > > Did you see this message?: > http://permalink.gmane.org/gmane.comp.ipod.gtkpod.user/2033 > > Adding songs to the TreeView is what is taking almost all the time in > pm_selection_changed_cb(): > > pm_selection_changed_cb enter: 2098.201221 sec > pm_selection_changed_cb before listing: 2098.214338 sec > pm_selection_changed_cb after listing: 2150.997785 sec > pm_selection_changed_cb exit: 2151.172406 sec > > It takes about ~53 seconds to do the for loop that add the tracks to the > TreeView. > > Then st_selection_changed_cb() is called several times (4), and the > timings for it are a little different (the first call): > > st_selection_changed_cb enter (inst: 0): 2151.504683 sec > st_selection_changed_cb after st_init: 2178.739254 sec > st_selection_changed_cb before loading tracks: 2178.739273 sec > st_selection_changed_cb after loading tracks: 2232.149276 sec > st_selection_changed_cb exit: 2232.376281 sec > > Note that the time between pm_selection_changed_cb() exit and > st_selection_changed_cb() enter is almost depreciable, so there is > nothing interesting between them (the same goes between > st_selection_changed_cb() calls). > > It passes a non-depreciable amount of time between > st_selection_changed_cb() enters and st_init() is finished (~27 > seconds), which might deserve some more isolation but looking at the > callgrind output I think it's probably removing the songs from the > TreeView what's taking so much time. Then a new loop adding songs is > measured, which takes again about ~54 seconds. Finally, the time between > the loop ends and st_selection_changed_cb() exists is depreciable. > > So I think the problem is quite isolated, what I don't know is if gtkpod > can do anything about it. As I said before, I'm using other GTK > applications that uses TreeViews with thousands of elements (like gmpc), > but never had this performance problems with them, so maybe there is > something gtkpod is doing wrong (or in a slow way) when manipulating > TreeViews. > Lucas, I'm responsible for bringing this part of Gtkpod's code to a decent speed with large collections. It used to be like you describe or worse. Although I'm still using the version of Gtkpod bundled by Debian, I see these files haven't changed since 2009, and the last change was just moving code around, which is well before the version I'm running. I'm wondering if there's anything special in your GTK+ or Gtkpod configuration that's triggering this behavior. Something in the GTK+ theme you're using? Unfortunately I'm practically a GTK+ illiterate, so I don't think I can be of big help if I can't reproduce this problem, and I haven't spotted any speed regressions while using Gtkpod myself. I suggest looking at bottlenecks in the call graph. From your e-mail I gather that some of the signals triggered by gtk_list_store_append might be causing some expensive computation to happen that can probably be avoided. I haven't used callgrind myself, and while probably it's great, I had lots of fun working with Google's perftools. I suggest trying both. I tried 2 or 3 profilers for this project until I settled with perftools. Suerte, P.S.: "despreciable" se traduce "insignificant" y el opuesto "significant", entre otros. |
From: Leandro L. <lu...@ll...> - 2010-07-11 22:40:46
|
Javier Kohen, el 11 de julio a las 21:46 me escribiste: [snip] > I'm wondering if there's anything special in your GTK+ or Gtkpod > configuration that's triggering this behavior. I'm wondering the same thing! :) > Something in the GTK+ theme you're using? I just tried changing it for a more popular one (Industrial and Clearlooks) and same problem with both. =( > Unfortunately I'm practically a GTK+ illiterate, so I don't think > I can be of big help if I can't reproduce this problem, and I haven't > spotted any speed regressions while using Gtkpod myself. > > I suggest looking at bottlenecks in the call graph. From your e-mail I > gather that some of the signals triggered by gtk_list_store_append might be > causing some expensive computation to happen that can probably be avoided. I > haven't used callgrind myself, and while probably it's great, I had lots of > fun working with Google's perftools. I suggest trying both. I tried 2 or 3 > profilers for this project until I settled with perftools. Unfortunately I don't have much time to profile GTK+ right now, and the odd thing is, I'm having this problem only with gtkpod. I think I will point this thread in the GTK ML and see if someone can bring a little light to this issue. > Suerte, Gracias =) > P.S.: "despreciable" se traduce "insignificant" y el opuesto "significant", > entre otros. Gracias nuevamente. -- Leandro Lucarella (AKA luca) http://llucax.com.ar/ ---------------------------------------------------------------------- GPG Key: 5F5A8D05 (F8CD F9A7 BF00 5431 4145 104C 949E BFB6 5F5A 8D05) ---------------------------------------------------------------------- Salvajes, de traje, me quieren enseñar Salvajes, de traje, me quieren educar |
From: Leandro L. <lu...@ll...> - 2010-07-08 23:14:46
|
P.G. Richardson, el 8 de julio a las 08:51 me escribiste: > As you state, it works on ubuntu and I have tested so far on fedora and > mandriva with no repeat of the problem so remain a little in the dark. > > Can you confirm whether your debian and ubuntu boxes are running the same > version of libgpod? > > What ipod model are you trying this with or is it just the playlist entry > for the local music library? > > Any testing you can do would be much appreciated. Here is a GDB session, it looks like the program is really working, but it takes too long, while the program was "frozen" (the UI really) I pressed Ctrl-C once in a while to see what was going on, and it looked like it really reading stuff from the iPod (please keep reading after the GDB session log): GNU gdb (GDB) 7.1-debian Copyright (C) 2010 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-linux-gnu". For bug reporting instructions, please see: <http://www.gnu.org/software/gdb/bugs/>... Traceback (most recent call last): File "<string>", line 3, in <module> ImportError: No module named libstdcxx.v6.printers /home/luca/.gdbinit:7: Error in sourced command file: Error while executing Python code. Reading symbols from /usr/local/bin/gtkpod...done. (gdb) run Starting program: /usr/local/bin/gtkpod [Thread debugging using libthread_db enabled] (gtkpod:4212): Gtk-WARNING **: gtk_menu_attach_to_widget(): menu already attached to GtkImageMenuItem [New Thread 0x7fffeb7a0710 (LWP 4218)] [Thread 0x7fffeb7a0710 (LWP 4218) exited] [New Thread 0x7fffeb7a0710 (LWP 4219)] ^C Program received signal SIGINT, Interrupt. 0x00007ffff572166c in ?? () from /usr/lib/libgobject-2.0.so.0 (gdb) bt #0 0x00007ffff572166c in ?? () from /usr/lib/libgobject-2.0.so.0 #1 0x00007ffff4e51c6d in g_hash_table_lookup () from /lib/libglib-2.0.so.0 #2 0x00007ffff5723aad in g_param_spec_pool_lookup () from /usr/lib/libgobject-2.0.so.0 #3 0x00007ffff571fbae in g_object_set_property () from /usr/lib/libgobject-2.0.so.0 #4 0x00007fffecfdb52d in ?? () from /usr/lib/gtk-2.0/modules/libgail.so #5 0x00007fffecfdf4bd in ?? () from /usr/lib/gtk-2.0/modules/libgail.so #6 0x00007fffecb9eb43 in ?? () from /usr/lib/gtk-2.0/modules/libatk-bridge.so #7 0x00007ffff572fe19 in ?? () from /usr/lib/libgobject-2.0.so.0 #8 0x00007ffff5731a76 in g_signal_emit_valist () from /usr/lib/libgobject-2.0.so.0 #9 0x00007ffff5731d93 in g_signal_emit_by_name () from /usr/lib/libgobject-2.0.so.0 #10 0x00007fffecfdde6d in ?? () from /usr/lib/gtk-2.0/modules/libgail.so #11 0x00007ffff571a47e in g_closure_invoke () from /usr/lib/libgobject-2.0.so.0 #12 0x00007ffff57307f4 in ?? () from /usr/lib/libgobject-2.0.so.0 #13 0x00007ffff5731a76 in g_signal_emit_valist () from /usr/lib/libgobject-2.0.so.0 #14 0x00007ffff5731fc3 in g_signal_emit () from /usr/lib/libgobject-2.0.so.0 #15 0x00007ffff74a50e0 in gtk_list_store_insert () from /usr/lib/libgtk-x11-2.0.so.0 #16 0x00000000004474cb in tm_add_track_to_track_model (track=0x1490e00, into_iter=0x0) at display_tracks.c:744 #17 0x000000000043aa3f in st_add_track (track=0x1490e00, final=0, display=1, inst=2) at display_sorttabs.c:1526 #18 0x000000000043a921 in st_add_track_normal (track=0x1490e00, final=0, display=1, inst=1) at display_sorttabs.c:1458 #19 st_add_track (track=0x1490e00, final=0, display=1, inst=1) at display_sorttabs.c:1538 #20 0x000000000043b60a in st_page_selected_cb (data=<value optimized out>) at display_sorttabs.c:1702 #21 0x00007ffff4e606c2 in g_main_context_dispatch () from /lib/libglib-2.0.so.0 #22 0x00007ffff4e64538 in ?? () from /lib/libglib-2.0.so.0 #23 0x00007ffff4e64a45 in g_main_loop_run () from /lib/libglib-2.0.so.0 #24 0x00007ffff74a8647 in gtk_main () from /usr/lib/libgtk-x11-2.0.so.0 #25 0x000000000045b232 in main (argc=1, argv=0x7fffffffe348) at main.c:67 (gdb) c Continuing. ^C Program received signal SIGINT, Interrupt. 0x00007ffff4e52b90 in g_hash_table_remove () from /lib/libglib-2.0.so.0 (gdb) thread apply all bt Thread 3 (Thread 0x7fffeb7a0710 (LWP 4219)): #0 0x00007ffff41e57dd in nanosleep () at ../sysdeps/unix/syscall-template.S:82 #1 0x0000000000459a9a in th_space_thread (gp=<value optimized out>) at info.c:751 #2 0x00007ffff4e896e4 in ?? () from /lib/libglib-2.0.so.0 #3 0x00007ffff41dd8ba in start_thread (arg=<value optimized out>) at pthread_create.c:300 #4 0x00007ffff3f4501d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112 #5 0x0000000000000000 in ?? () Thread 1 (Thread 0x7ffff7ea87c0 (LWP 4212)): #0 0x00007ffff4e52b90 in g_hash_table_remove () from /lib/libglib-2.0.so.0 #1 0x00007fffec6faa4c in bonobo_running_context_remove_object_T () from /usr/lib/libbonobo-2.so.0 #2 0x00007fffec6f1568 in bonobo_object_unref () from /usr/lib/libbonobo-2.so.0 #3 0x00007fffecb9df9d in ?? () from /usr/lib/gtk-2.0/modules/libatk-bridge.so #4 0x00007fffecb9f2a4 in ?? () from /usr/lib/gtk-2.0/modules/libatk-bridge.so #5 0x00007ffff572fe19 in ?? () from /usr/lib/libgobject-2.0.so.0 #6 0x00007ffff5731a76 in g_signal_emit_valist () from /usr/lib/libgobject-2.0.so.0 #7 0x00007ffff5731fc3 in g_signal_emit () from /usr/lib/libgobject-2.0.so.0 #8 0x00007ffff6eae9f2 in ?? () from /usr/lib/libatk-1.0.so.0 #9 0x00007ffff571a47e in g_closure_invoke () from /usr/lib/libgobject-2.0.so.0 #10 0x00007ffff572fcc1 in ?? () from /usr/lib/libgobject-2.0.so.0 #11 0x00007ffff5731a76 in g_signal_emit_valist () from /usr/lib/libgobject-2.0.so.0 #12 0x00007ffff5731fc3 in g_signal_emit () from /usr/lib/libgobject-2.0.so.0 #13 0x00007ffff571e459 in ?? () from /usr/lib/libgobject-2.0.so.0 #14 0x00007ffff57203bc in g_object_notify () from /usr/lib/libgobject-2.0.so.0 #15 0x00007fffecfc221f in gail_cell_initialise () from /usr/lib/gtk-2.0/modules/libgail.so #16 0x00007fffecfdf49c in ?? () from /usr/lib/gtk-2.0/modules/libgail.so #17 0x00007fffecb9eb43 in ?? () from /usr/lib/gtk-2.0/modules/libatk-bridge.so #18 0x00007ffff572fe19 in ?? () from /usr/lib/libgobject-2.0.so.0 #19 0x00007ffff5731a76 in g_signal_emit_valist () from /usr/lib/libgobject-2.0.so.0 #20 0x00007ffff5731d93 in g_signal_emit_by_name () from /usr/lib/libgobject-2.0.so.0 #21 0x00007fffecfdde6d in ?? () from /usr/lib/gtk-2.0/modules/libgail.so #22 0x00007ffff571a47e in g_closure_invoke () from /usr/lib/libgobject-2.0.so.0 #23 0x00007ffff57307f4 in ?? () from /usr/lib/libgobject-2.0.so.0 #24 0x00007ffff5731a76 in g_signal_emit_valist () from /usr/lib/libgobject-2.0.so.0 #25 0x00007ffff5731fc3 in g_signal_emit () from /usr/lib/libgobject-2.0.so.0 #26 0x00007ffff74a50e0 in gtk_list_store_insert () from /usr/lib/libgtk-x11-2.0.so.0 #27 0x00000000004474cb in tm_add_track_to_track_model (track=0x13bdd00, into_iter=0x0) at display_tracks.c:744 #28 0x000000000043aa3f in st_add_track (track=0x13bdd00, final=0, display=1, inst=2) at display_sorttabs.c:1526 #29 0x000000000043a921 in st_add_track_normal (track=0x13bdd00, final=0, display=1, inst=1) at display_sorttabs.c:1458 #30 st_add_track (track=0x13bdd00, final=0, display=1, inst=1) at display_sorttabs.c:1538 #31 0x000000000043b60a in st_page_selected_cb (data=<value optimized out>) at display_sorttabs.c:1702 #32 0x00007ffff4e606c2 in g_main_context_dispatch () from /lib/libglib-2.0.so.0 #33 0x00007ffff4e64538 in ?? () from /lib/libglib-2.0.so.0 #34 0x00007ffff4e64a45 in g_main_loop_run () from /lib/libglib-2.0.so.0 #35 0x00007ffff74a8647 in gtk_main () from /usr/lib/libgtk-x11-2.0.so.0 #36 0x000000000045b232 in main (argc=1, argv=0x7fffffffe348) at main.c:67 (gdb) c Continuing. ^C Program received signal SIGINT, Interrupt. memcpy () at ../sysdeps/x86_64/memcpy.S:91 91 ../sysdeps/x86_64/memcpy.S: No existe el fichero o el directorio. in ../sysdeps/x86_64/memcpy.S (gdb) thread apply all bt Thread 3 (Thread 0x7fffeb7a0710 (LWP 4219)): #0 0x00007ffff41e57dd in nanosleep () at ../sysdeps/unix/syscall-template.S:82 #1 0x0000000000459a9a in th_space_thread (gp=<value optimized out>) at info.c:751 #2 0x00007ffff4e896e4 in ?? () from /lib/libglib-2.0.so.0 #3 0x00007ffff41dd8ba in start_thread (arg=<value optimized out>) at pthread_create.c:300 #4 0x00007ffff3f4501d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112 #5 0x0000000000000000 in ?? () Thread 1 (Thread 0x7ffff7ea87c0 (LWP 4212)): #0 memcpy () at ../sysdeps/x86_64/memcpy.S:91 #1 0x00007ffff75851c6 in gtk_tree_path_copy () from /usr/lib/libgtk-x11-2.0.so.0 #2 0x00007fffecfded7a in ?? () from /usr/lib/gtk-2.0/modules/libgail.so #3 0x00007fffecfdf249 in ?? () from /usr/lib/gtk-2.0/modules/libgail.so #4 0x00007fffecb9eb43 in ?? () from /usr/lib/gtk-2.0/modules/libatk-bridge.so #5 0x00007ffff572fe19 in ?? () from /usr/lib/libgobject-2.0.so.0 #6 0x00007ffff5731a76 in g_signal_emit_valist () from /usr/lib/libgobject-2.0.so.0 #7 0x00007ffff5731d93 in g_signal_emit_by_name () from /usr/lib/libgobject-2.0.so.0 #8 0x00007fffecfdde6d in ?? () from /usr/lib/gtk-2.0/modules/libgail.so #9 0x00007ffff571a47e in g_closure_invoke () from /usr/lib/libgobject-2.0.so.0 #10 0x00007ffff57307f4 in ?? () from /usr/lib/libgobject-2.0.so.0 #11 0x00007ffff5731a76 in g_signal_emit_valist () from /usr/lib/libgobject-2.0.so.0 #12 0x00007ffff5731fc3 in g_signal_emit () from /usr/lib/libgobject-2.0.so.0 #13 0x00007ffff74a50e0 in gtk_list_store_insert () from /usr/lib/libgtk-x11-2.0.so.0 #14 0x00000000004474cb in tm_add_track_to_track_model (track=0x12a9ce0, into_iter=0x0) at display_tracks.c:744 #15 0x000000000043aa3f in st_add_track (track=0x12a9ce0, final=0, display=1, inst=2) at display_sorttabs.c:1526 #16 0x000000000043a921 in st_add_track_normal (track=0x12a9ce0, final=0, display=1, inst=1) at display_sorttabs.c:1458 #17 st_add_track (track=0x12a9ce0, final=0, display=1, inst=1) at display_sorttabs.c:1538 #18 0x000000000043b60a in st_page_selected_cb (data=<value optimized out>) at display_sorttabs.c:1702 #19 0x00007ffff4e606c2 in g_main_context_dispatch () from /lib/libglib-2.0.so.0 #20 0x00007ffff4e64538 in ?? () from /lib/libglib-2.0.so.0 #21 0x00007ffff4e64a45 in g_main_loop_run () from /lib/libglib-2.0.so.0 #22 0x00007ffff74a8647 in gtk_main () from /usr/lib/libgtk-x11-2.0.so.0 #23 0x000000000045b232 in main (argc=1, argv=0x7fffffffe348) at main.c:67 (gdb) up #1 0x00007ffff75851c6 in gtk_tree_path_copy () from /usr/lib/libgtk-x11-2.0.so.0 (gdb) #2 0x00007fffecfded7a in ?? () from /usr/lib/gtk-2.0/modules/libgail.so (gdb) #3 0x00007fffecfdf249 in ?? () from /usr/lib/gtk-2.0/modules/libgail.so (gdb) #4 0x00007fffecb9eb43 in ?? () from /usr/lib/gtk-2.0/modules/libatk-bridge.so (gdb) #5 0x00007ffff572fe19 in ?? () from /usr/lib/libgobject-2.0.so.0 (gdb) #6 0x00007ffff5731a76 in g_signal_emit_valist () from /usr/lib/libgobject-2.0.so.0 (gdb) #7 0x00007ffff5731d93 in g_signal_emit_by_name () from /usr/lib/libgobject-2.0.so.0 (gdb) #8 0x00007fffecfdde6d in ?? () from /usr/lib/gtk-2.0/modules/libgail.so (gdb) #9 0x00007ffff571a47e in g_closure_invoke () from /usr/lib/libgobject-2.0.so.0 (gdb) #10 0x00007ffff57307f4 in ?? () from /usr/lib/libgobject-2.0.so.0 (gdb) #11 0x00007ffff5731a76 in g_signal_emit_valist () from /usr/lib/libgobject-2.0.so.0 (gdb) #12 0x00007ffff5731fc3 in g_signal_emit () from /usr/lib/libgobject-2.0.so.0 (gdb) #13 0x00007ffff74a50e0 in gtk_list_store_insert () from /usr/lib/libgtk-x11-2.0.so.0 (gdb) #14 0x00000000004474cb in tm_add_track_to_track_model (track=0x12a9ce0, into_iter=0x0) at display_tracks.c:744 744 gtk_list_store_append (get_model_as_store (model), &iter); (gdb) print The history is empty. (gdb) list 739 { 740 convert_iter (model, into_iter, &iter); 741 } 742 else 743 { 744 gtk_list_store_append (get_model_as_store (model), &iter); 745 } 746 747 gtk_list_store_set (get_model_as_store (model), &iter, READOUT_COL, track, -1); 748 /* update_model_view (model); -- not needed */ (gdb) print track $1 = (Track *) 0x12a9ce0 (gdb) print *track $2 = { itdb = 0x113f570, title = 0x12aa010 "Waking Up", ipod_path = 0x12aa070 ":iPod_Control:Music:F10:libgpod011370.mp3", album = 0x12aa050 "Elastica", artist = 0x12aa030 "Elastica", genre = 0x12aa0d0 "Alternative", filetype = 0x12a9ff0 "MPEG audio file", comment = 0x18d3910 "", category = 0x18d3950 "", composer = 0x18d38f0 "", grouping = 0x18d3930 "", description = 0x18d3970 "", podcasturl = 0x18d3990 "", podcastrss = 0x18d39b0 "", chapterdata = 0x122bd40, subtitle = 0x18d39d0 "", tvshow = 0x18d39f0 "", tvepisode = 0x18d3a10 "", tvnetwork = 0x18d3a30 "", albumartist = 0x18d3a50 "", keywords = 0x0, sort_artist = 0x18d3a70 "", sort_title = 0x18d3a90 "", sort_album = 0x18d3ab0 "", sort_albumartist = 0x18d3ad0 "", sort_composer = 0x18d3af0 "", sort_tvshow = 0x18d3b10 "", id = 664, size = 4850987, tracklen = 195612, cd_nr = 0, cds = 0, track_nr = 11, tracks = 0, bitrate = 196, samplerate = 44100, samplerate_low = 0, year = 1995, volume = 0, soundcheck = 943, time_added = 1269343216, time_modified = 1269343085, time_played = 1278238482, bookmark_time = 0, rating = 0, playcount = 1, playcount2 = 0, recent_playcount = 1, transferred = 1, BPM = 0, app_rating = 0 '\000', type1 = 0 '\000', type2 = 0 '\000', compilation = 0 '\000', starttime = 0, stoptime = 0, checked = 0 '\000', dbid = 17069759481495381192, drm_userid = 0, visible = 1, filetype_marker = 1297101600, artwork_count = 1, artwork_size = 36797, samplerate2 = 44100, unk126 = 65535, unk132 = 0, time_released = 0, unk144 = 12, explicit_flag = 0, ---Type <return> to continue, or q <return> to quit---q Quit (gdb) c Continuing. ^C Program received signal SIGINT, Interrupt. 0x00007ffff4e7e221 in g_slice_alloc () from /lib/libglib-2.0.so.0 (gdb) thread apply all bt Thread 3 (Thread 0x7fffeb7a0710 (LWP 4219)): #0 0x00007ffff41e57dd in nanosleep () at ../sysdeps/unix/syscall-template.S:82 #1 0x0000000000459a9a in th_space_thread (gp=<value optimized out>) at info.c:751 #2 0x00007ffff4e896e4 in ?? () from /lib/libglib-2.0.so.0 #3 0x00007ffff41dd8ba in start_thread (arg=<value optimized out>) at pthread_create.c:300 #4 0x00007ffff3f4501d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112 #5 0x0000000000000000 in ?? () Thread 1 (Thread 0x7ffff7ea87c0 (LWP 4212)): #0 0x00007ffff4e7e221 in g_slice_alloc () from /lib/libglib-2.0.so.0 #1 0x00007ffff4e5e289 in g_list_copy () from /lib/libglib-2.0.so.0 #2 0x00007fffecfded0e in ?? () from /usr/lib/gtk-2.0/modules/libgail.so #3 0x00007fffecfded8e in ?? () from /usr/lib/gtk-2.0/modules/libgail.so #4 0x00007fffecfdf249 in ?? () from /usr/lib/gtk-2.0/modules/libgail.so #5 0x00007fffecb9eb43 in ?? () from /usr/lib/gtk-2.0/modules/libatk-bridge.so #6 0x00007ffff572fe19 in ?? () from /usr/lib/libgobject-2.0.so.0 #7 0x00007ffff5731a76 in g_signal_emit_valist () from /usr/lib/libgobject-2.0.so.0 #8 0x00007ffff5731d93 in g_signal_emit_by_name () from /usr/lib/libgobject-2.0.so.0 #9 0x00007fffecfdde6d in ?? () from /usr/lib/gtk-2.0/modules/libgail.so #10 0x00007ffff571a47e in g_closure_invoke () from /usr/lib/libgobject-2.0.so.0 #11 0x00007ffff57307f4 in ?? () from /usr/lib/libgobject-2.0.so.0 #12 0x00007ffff5731a76 in g_signal_emit_valist () from /usr/lib/libgobject-2.0.so.0 #13 0x00007ffff5731fc3 in g_signal_emit () from /usr/lib/libgobject-2.0.so.0 #14 0x00007ffff74a50e0 in gtk_list_store_insert () from /usr/lib/libgtk-x11-2.0.so.0 #15 0x00000000004474cb in tm_add_track_to_track_model (track=0x123a800, into_iter=0x0) at display_tracks.c:744 #16 0x000000000043aa3f in st_add_track (track=0x123a800, final=0, display=1, inst=2) at display_sorttabs.c:1526 #17 0x000000000043a921 in st_add_track_normal (track=0x123a800, final=0, display=1, inst=1) at display_sorttabs.c:1458 #18 st_add_track (track=0x123a800, final=0, display=1, inst=1) at display_sorttabs.c:1538 #19 0x000000000043b60a in st_page_selected_cb (data=<value optimized out>) at display_sorttabs.c:1702 #20 0x00007ffff4e606c2 in g_main_context_dispatch () from /lib/libglib-2.0.so.0 #21 0x00007ffff4e64538 in ?? () from /lib/libglib-2.0.so.0 #22 0x00007ffff4e64a45 in g_main_loop_run () from /lib/libglib-2.0.so.0 #23 0x00007ffff74a8647 in gtk_main () from /usr/lib/libgtk-x11-2.0.so.0 #24 0x000000000045b232 in main (argc=1, argv=0x7fffffffe348) at main.c:67 (gdb) up 15 #15 0x00000000004474cb in tm_add_track_to_track_model (track=0x123a800, into_iter=0x0) at display_tracks.c:744 744 gtk_list_store_append (get_model_as_store (model), &iter); (gdb) up #16 0x000000000043aa3f in st_add_track (track=0x123a800, final=0, display=1, inst=2) at display_sorttabs.c:1526 1526 tm_add_track_to_track_model(track, NULL); (gdb) display *track 1: *track = { itdb = 0x113f570, title = 0x123a790 "Shake Well Before Opening", ipod_path = 0 After some minutes (I'd say in the order of 15 minutes, but I didn't really checked), the UI was responding again, but I think I clicked elsewhere while frozen, so I couldn't see the song list (Podcasts was selected). When I clicked in the iPod main playlist, it froze again. But I waited again about the same time and it came back and I could see the list of songs. Clicking on an album, freezes it again, but for a much shorter period of time, so the freeze time looks proportional to the songs read. So it's working, it's just way too slooooow. Any ideas on what can be causing the slowness? Thanks. -- Leandro Lucarella (AKA luca) http://llucax.com.ar/ ---------------------------------------------------------------------- GPG Key: 5F5A8D05 (F8CD F9A7 BF00 5431 4145 104C 949E BFB6 5F5A 8D05) ---------------------------------------------------------------------- Y vos, me dijiste que soy, un abismo de silencio. Será, porque vos no escuchas, que yo grito por dentro. |
From: Leandro L. <lu...@ll...> - 2010-07-09 21:42:28
|
P.G. Richardson, el 9 de julio a las 08:29 me escribiste: [snip] > > After some minutes (I'd say in the order of 15 minutes, but I didn't > > really > > checked), the UI was responding again, but I think I clicked elsewhere > > while > > frozen, so I couldn't see the song list (Podcasts was selected). When I > > clicked > > in the iPod main playlist, it froze again. But I waited again about the > > same > > time and it came back and I could see the list of songs. Clicking on an > > album, > > freezes it again, but for a much shorter period of time, so the freeze > > time > > looks proportional to the songs read. So it's working, it's just way too > > slooooow. > > Try and get some obvious things out of the way... > > Does the machine have USB 1.1 or 2, ie. is USB slow when accessing other > devices outside of gtkpod? USB 2 and no, I've tried several different USB ports just in case and have the same issues. The chipset is Intel (in case it helps). I've done some testing using the device as an USB disk and the results are a little disorienting. Doing a dd on the whole partition yields a good 14.1 MB/s read rate. But when using the device with nautilus for example, to copy a file, it copies about ~170Mb and then hangs too (the file is about 200MB and the device have about 280MB of free space). Doing an hdparm -t on the device while it's hung, hdparm freezes for a while too, but after that it completes the measure and reports a decent transfer speed (about 14MB/s too). I guess this couldn't be gtkpod's fault, but I find a little weird that gtkpod uses about 50% of the CPU while scanning for songs (2GHz quad-core). And it looks like writing could be a little slow, but not reading, does gtkpod write anything while scanning for songs. I tried to break tm_add_track_to_track_model() using GDB to see how long took each song to be scanned and it seems to be instantly really, so I guess there is something else going on. > If the versions are the same for gtkpod and libgpod, what difference is > there in versions for the support libraries between it and your debian > box? I have to check, but having gtk as a dependency I guess I would have to end up checking hundreds of libraries :S -- Leandro Lucarella (AKA luca) http://llucax.com.ar/ ---------------------------------------------------------------------- GPG Key: 5F5A8D05 (F8CD F9A7 BF00 5431 4145 104C 949E BFB6 5F5A 8D05) ---------------------------------------------------------------------- Hoy estuvimos en el museo de antropología, pero yo voy a volver para estar por lo menos un día ahí adentro... es una locura, como Disney pero de indigenas -- Carla Lucarella (10/2008 contando de su viaje a México) |
From: Leandro L. <lu...@ll...> - 2010-07-09 23:53:27
|
Leandro Lucarella, el 9 de julio a las 18:42 me escribiste: > I tried to break tm_add_track_to_track_model() using GDB to see how long > took each song to be scanned and it seems to be instantly really, so > I guess there is something else going on. I'm doing some profiling and, correct me if I'm wrong, but gtkpod load all the songs at the beginning of the program, and not each time one clicks on the iPod playlist, so I that is correct, an I/O problem involving the device is discarded. It looks like it's GTK which somehow is slow. Manipulating the TreeViews seems to be what's taking so long. I've compiled gtkpod setting the macro DEBUG_TIMING and added a couple more prints and this is the result: pm_selection_changed_cb enter: 2098.201221 sec pm_selection_changed_cb before listing: 2098.214338 sec pm_selection_changed_cb after listing: 2150.997785 sec pm_selection_changed_cb exit: 2151.172406 sec st_selection_changed_cb enter (inst: 0): 2151.504683 sec st_selection_changed_cb after st_init: 2178.739254 sec st_selection_changed_cb before loading tracks: 2178.739273 sec st_selection_changed_cb after loading tracks: 2232.149276 sec st_selection_changed_cb exit: 2232.376281 sec st_selection_changed_cb enter (inst: 1): 2232.376300 sec st_selection_changed_cb after st_init: 2260.392100 sec st_selection_changed_cb before loading tracks: 2260.392119 sec st_selection_changed_cb after loading tracks: 2315.961767 sec st_selection_changed_cb exit: 2316.018309 sec st_selection_changed_cb enter (inst: 1): 2316.116774 sec st_selection_changed_cb after st_init: 2343.740650 sec st_selection_changed_cb before loading tracks: 2343.740677 sec st_selection_changed_cb after loading tracks: 2399.858041 sec st_selection_changed_cb exit: 2399.920906 sec st_selection_changed_cb enter (inst: 1): 2399.920933 sec st_selection_changed_cb after st_init: 2428.241284 sec st_selection_changed_cb before loading tracks: 2428.241303 sec st_selection_changed_cb after loading tracks: 2483.904216 sec st_selection_changed_cb exit: 2483.962219 sec The after and before listing/loading tracks was added like this: #if DEBUG_TIMING g_get_current_time (&time); printf ("pm_selection_changed_cb before listing: %ld.%06ld sec\n", time.tv_sec % 3600, time.tv_usec); #endif for (gl=new_playlist->members; gl; gl=gl->next) { /* add all tracks to sort tab 0 */ Track *track = gl->data; st_add_track (track, FALSE, TRUE, 0); } #if DEBUG_TIMING g_get_current_time (&time); printf ("pm_selection_changed_cb after listing: %ld.%06ld sec\n", time.tv_sec % 3600, time.tv_usec); #endif iAt display_playlists.c:1518 and: #if DEBUG_TIMING || DEBUG_CB_INIT g_get_current_time (&time); printf ("st_selection_changed_cb before loading tracks: %ld.%06ld sec\n", time.tv_sec % 3600, time.tv_usec); #endif for (gl = new_entry->members; gl; gl = gl->next) { /* add all member tracks to next instance */ Track *track = gl->data; st_add_track(track, FALSE, TRUE, inst+1); } #if DEBUG_TIMING || DEBUG_CB_INIT g_get_current_time (&time); printf ("st_selection_changed_cb after loading tracks: %ld.%06ld sec\n", time.tv_sec % 3600, time.tv_usec); #endif (at display_sorttabs.c:~1930) "the after st_init()" was added after any st_init() call in st_selection_changed_cb(). pm_selection_changed_cb() and st_selection_changed_cb() are both taking an eternity, and both apparently because of the TreeView manipulation. Besides that being too slow, I don't know why those callbacks are called so many times, since only one click on the iPod playlist triggered all that callbacks (which makes things even worse). I have no idea why this is happening though, all I can say is that I'm using other GTK applications that make heavy use of TreeView; like gmpc, where I can list about 25k songs (much more than I have in the iPod) in a fraction of a second. To makes things worse, libgtk-2.0 is the same version in the Ubuntu box where it's slow than in the box where it works fine (which BTW is a Pentium M 1.7GHz, much less processing power than the box where it's incredibly slow). Any ideas or suggestions are welcome. -- Leandro Lucarella (AKA luca) http://llucax.com.ar/ ---------------------------------------------------------------------- GPG Key: 5F5A8D05 (F8CD F9A7 BF00 5431 4145 104C 949E BFB6 5F5A 8D05) ---------------------------------------------------------------------- Y tuve amores, que fue uno sólo El que me dejó de a pie y me enseñó todo... |
From: Leandro L. <lu...@ll...> - 2010-07-10 03:21:52
|
Leandro Lucarella, el 9 de julio a las 20:53 me escribiste: > pm_selection_changed_cb() and st_selection_changed_cb() are both taking > an eternity, and both apparently because of the TreeView manipulation. > Besides that being too slow, I don't know why those callbacks are called > so many times, since only one click on the iPod playlist triggered all > that callbacks (which makes things even worse). I did a run using valgrind's callgrind and those 2 functions are taking ~87% of the work. Here is the callgrind log file, you can explore it with kcachegrind to see if you find anything particularly strange: http://www.llucax.com.ar/tmp/callgrind.out.16685.bz2 (~450KB download, ~2.5MB uncompressed) The logged session is not complete until all the data was shown, just a couple of calls to pm_selection_changed_cb() and st_selection_changed_cb(), it took several hours to reach this point :) Here is the log (just using DEBUG_TIMING, without my extra printf()s): pm_selection_changed_cb enter: 526.562090 sec pm_selection_changed_cb exit: 3541.055112 sec st_selection_changed_cb enter (inst: 0): 3578.167885 sec st_selection_changed_cb exit: 438.241159 sec st_selection_changed_cb enter (inst: 1): 438.241632 sec st_selection_changed_cb exit: 852.802046 sec st_selection_changed_cb enter (inst: 1): 859.227562 sec [killed] Thanks. -- Leandro Lucarella (AKA luca) http://llucax.com.ar/ ---------------------------------------------------------------------- GPG Key: 5F5A8D05 (F8CD F9A7 BF00 5431 4145 104C 949E BFB6 5F5A 8D05) ---------------------------------------------------------------------- All evidence has been buried All tapes have been erased But your footsteps give you away So you're backtracking |
From: phantomjinx <p.g...@ph...> - 2010-07-11 16:58:42
|
On 10/07/10 04:21, Leandro Lucarella wrote: > Leandro Lucarella, el 9 de julio a las 20:53 me escribiste: > >> pm_selection_changed_cb() and st_selection_changed_cb() are both taking >> an eternity, and both apparently because of the TreeView manipulation. >> Besides that being too slow, I don't know why those callbacks are called >> so many times, since only one click on the iPod playlist triggered all >> that callbacks (which makes things even worse). >> > I did a run using valgrind's callgrind and those 2 functions are taking > ~87% of the work. Here is the callgrind log file, you can explore it > with kcachegrind to see if you find anything particularly strange: > http://www.llucax.com.ar/tmp/callgrind.out.16685.bz2 > (~450KB download, ~2.5MB uncompressed) > > The logged session is not complete until all the data was shown, just > a couple of calls to pm_selection_changed_cb() and > st_selection_changed_cb(), it took several hours to reach this point :) > > Here is the log (just using DEBUG_TIMING, without my extra printf()s): > pm_selection_changed_cb enter: 526.562090 sec > pm_selection_changed_cb exit: 3541.055112 sec > st_selection_changed_cb enter (inst: 0): 3578.167885 sec > st_selection_changed_cb exit: 438.241159 sec > st_selection_changed_cb enter (inst: 1): 438.241632 sec > st_selection_changed_cb exit: 852.802046 sec > st_selection_changed_cb enter (inst: 1): 859.227562 sec > [killed] > Thanks for your efforts so far. I think it might be time to take pm_selection_changed_cb to pieces as my suspicion is the following: - Change selection to ipod master playlist causes pm_selection_changed_cb - st_init called and tends to call st_selection_changed_cb for each filter tab that is re-inited I would say that the performance bottleneck is due to st_init being called and st_selection_changed_cb being fired too many times So, can you try commenting sections of the code out in pm_selection_changed_cb and see if you can isolate exactly which part of the code is taking so long? Cheers PGR |
From: Leandro L. <lu...@ll...> - 2010-07-11 18:00:27
|
phantomjinx, el 11 de julio a las 17:58 me escribiste: > On 10/07/10 04:21, Leandro Lucarella wrote: > > Leandro Lucarella, el 9 de julio a las 20:53 me escribiste: > > > >> pm_selection_changed_cb() and st_selection_changed_cb() are both taking > >> an eternity, and both apparently because of the TreeView manipulation. > >> Besides that being too slow, I don't know why those callbacks are called > >> so many times, since only one click on the iPod playlist triggered all > >> that callbacks (which makes things even worse). > >> > > I did a run using valgrind's callgrind and those 2 functions are taking > > ~87% of the work. Here is the callgrind log file, you can explore it > > with kcachegrind to see if you find anything particularly strange: > > http://www.llucax.com.ar/tmp/callgrind.out.16685.bz2 > > (~450KB download, ~2.5MB uncompressed) > > > > The logged session is not complete until all the data was shown, just > > a couple of calls to pm_selection_changed_cb() and > > st_selection_changed_cb(), it took several hours to reach this point :) > > > > Here is the log (just using DEBUG_TIMING, without my extra printf()s): > > pm_selection_changed_cb enter: 526.562090 sec > > pm_selection_changed_cb exit: 3541.055112 sec > > st_selection_changed_cb enter (inst: 0): 3578.167885 sec > > st_selection_changed_cb exit: 438.241159 sec > > st_selection_changed_cb enter (inst: 1): 438.241632 sec > > st_selection_changed_cb exit: 852.802046 sec > > st_selection_changed_cb enter (inst: 1): 859.227562 sec > > [killed] > > > > Thanks for your efforts so far. Is the least I can do to thank you for gtkpod =) > I think it might be time to take pm_selection_changed_cb to pieces as my > suspicion is the following: > > - Change selection to ipod master playlist causes pm_selection_changed_cb > - st_init called and tends to call st_selection_changed_cb for each > filter tab that is re-inited > > I would say that the performance bottleneck is due to st_init being > called and st_selection_changed_cb being fired too many times > > So, can you try commenting sections of the code out in > pm_selection_changed_cb and see if you can isolate exactly which part of > the code is taking so long? Did you see this message?: http://permalink.gmane.org/gmane.comp.ipod.gtkpod.user/2033 Adding songs to the TreeView is what is taking almost all the time in pm_selection_changed_cb(): pm_selection_changed_cb enter: 2098.201221 sec pm_selection_changed_cb before listing: 2098.214338 sec pm_selection_changed_cb after listing: 2150.997785 sec pm_selection_changed_cb exit: 2151.172406 sec It takes about ~53 seconds to do the for loop that add the tracks to the TreeView. Then st_selection_changed_cb() is called several times (4), and the timings for it are a little different (the first call): st_selection_changed_cb enter (inst: 0): 2151.504683 sec st_selection_changed_cb after st_init: 2178.739254 sec st_selection_changed_cb before loading tracks: 2178.739273 sec st_selection_changed_cb after loading tracks: 2232.149276 sec st_selection_changed_cb exit: 2232.376281 sec Note that the time between pm_selection_changed_cb() exit and st_selection_changed_cb() enter is almost depreciable, so there is nothing interesting between them (the same goes between st_selection_changed_cb() calls). It passes a non-depreciable amount of time between st_selection_changed_cb() enters and st_init() is finished (~27 seconds), which might deserve some more isolation but looking at the callgrind output I think it's probably removing the songs from the TreeView what's taking so much time. Then a new loop adding songs is measured, which takes again about ~54 seconds. Finally, the time between the loop ends and st_selection_changed_cb() exists is depreciable. So I think the problem is quite isolated, what I don't know is if gtkpod can do anything about it. As I said before, I'm using other GTK applications that uses TreeViews with thousands of elements (like gmpc), but never had this performance problems with them, so maybe there is something gtkpod is doing wrong (or in a slow way) when manipulating TreeViews. I did a final test. I commented out the line: gtk_list_store_append (get_model_as_store (model), &iter); in display_tracks.c:744 (tm_add_track_to_track_model() function) and it loads the playlist instantly. Obviously I can't see any songs, but I can see all the cover art images. I can see in the callgrind log that gtk_list_store_append() is triggering some signals, maybe is that what's taking so much time, maybe is there a way to deactivate triggering that signals, but anyways, I think it's something that GTK developers should know better. What I can't understand is why this performance issue is only happening in that particular box :S Thanks. PS: Changing the preference value of sort_tab_num to 0 helps a little, as I think it avoids calling st_selection_changed_cb() so many times, but I can't easily filter music based on Album/Artist :( -- Leandro Lucarella (AKA luca) http://llucax.com.ar/ ---------------------------------------------------------------------- GPG Key: 5F5A8D05 (F8CD F9A7 BF00 5431 4145 104C 949E BFB6 5F5A 8D05) ---------------------------------------------------------------------- All evidence has been buried All tapes have been erased But your footsteps give you away So you're backtracking |
From: phantomjinx <p.g...@ph...> - 2010-07-17 23:10:26
|
Hi Mark, Have got around to solving your problem with gtkpod on Fedora 13. Seems that the new distro requires active relinking of the application against the dl library. Whether this mean much to you or not, the temporary workaround is below. I will update the git repo for the release as soon as possible. 1) open src/Makefile.am in an editor 2) Update the following line by including the -ldl: -gtkpod_LDADD = $(LIBS) -lm $(INTLLIBS) @LIBOBJS@ +gtkpod_LDADD = $(LIBS) -lm $(INTLLIBS) -ldl @LIBOBJS@ 3) Save the file and close editor 4) Run the autogen.sh script 5) make This should solve the problem and the app should compile. Thanks for the testing. Cheers and regards PGR On 09/07/10 03:22, Mark Morin wrote: > Still getting errors with make. Running fedora 13. Link to make output follows. > http://dl.dropbox.com/u/6289699/gtkpod-1.0.0%20%282%29.txt > > Sent from my iPod > > On Jul 7, 2010, at 5:35 PM, phantomjinx<p.g...@ph...> wrote: > > >> Hi people, >> >> Second beta of gtkpod with most of the fixes suggested since the weekend included. >> >> http://www.phantomjinx.co.uk/stuff/gtkpod-1.0.0-beta2.tar.gz >> >> Happy testing. >> >> Cheers >> >> PGR (a.k.a. phantomjinx) >> >> >> >> ------------------------------------------------------------------------------ >> This SF.net email is sponsored by Sprint >> What will you do first with EVO, the first 4G phone? >> Visit sprint.com/first -- http://p.sf.net/sfu/sprint-com-first >> _______________________________________________ >> Gtkpod-questions mailing list >> Gtk...@li... >> https://lists.sourceforge.net/lists/listinfo/gtkpod-questions >> |