On Sun, Jul 11, 2010 at 20:00, Leandro Lucarella <luca@llucax.com.ar> 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?:

Adding songs to the TreeView is what is taking almost all the time in

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

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


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.


P.S.: "despreciable" se traduce "insignificant" y el opuesto "significant", entre otros.