Thanks for sharing this tool and the research ! Some comments below. On Fri, 2009-12-11 at 22:00 -0800, Gabriel Burt wrote: > Hey all, > > I spent some time today playing with the --trace mono option[0]. It > prints out ENTER and LEAVE timestamps for every method call, filtered > by namespace or type or however you want. If you are on the latest > git, you can use 'make run-trace' to replicate my findings below. > > I wrote a little tool[1] to dump that data to a sqlite database, and > then I ran some queries on it. One of the more interesting is this > one[2], which shows which methods on the main thread took the most > time (during starting and immediately closing Banshee), not including > time spent in methods within assemblies in bin/ (except > Mono.Data.Sqlite) they called: > > ms calls class_and_method > ---- ------ --------------------------------------------------------------------------------------------- > 1949 313 Hyena.Data.Sqlite.HyenaSqliteCommand:WaitForResult > 942 20739 Hyena.Data.Sqlite.AbstractDatabaseColumn:SetValue > 886 1 Banshee.ServiceStack.ServiceManager:InitializeAddins > 753 1 Banshee.Gui.GtkBaseClient:Run > 554 4 Banshee.Gui.GtkBaseClient/<RunIdle>c__AnonStorey18:<>m__85 > 553 1 Banshee.ServiceStack.Client:OnStarted > 207 823 Hal.Device:QueryCapability > 161 758 Hyena.Data.Sqlite.SqliteModelProvider`1:Load > 143 8698 Hyena.Data.Sqlite.SqliteUtils:FromDbFormat > 137 11859 Hyena.Data.Sqlite.HyenaSqliteArrayDataReader:IsDBNull > 116 9699 Hyena.Data.Sqlite.HyenaSqliteArrayDataReader:GetValue > > So 1.9s was spent waiting for sqlite commands to return values, on the > main thread. .87 seconds was spent in InitializeAddins. The > Hal.Device querying also seems strange to be running on the main loop. I saw approximately the same figures for HyenaSqliteCommand:WaitForResult on a first run, but for the next runs the time was around 300 ms. This needs further investigations. The fact that those sqlite queries are run on the main thread is consistent with all the "HyenaSqliteConnection command issued from the main thread" messages I get with the --debug-sql option. I think the time spent in InitializeAddins goes up to 800 ms only if the addin cache is not present (in bin/addin-db-001/). On consecutive runs, it's less than 200 ms. > Anyway, just some interesting optimization research I'm still > digesting. It's possible my tool is buggy and these numbers are > completely off, but they seem reasonable enough to me. > > Gabriel > > [0] http://www.mono-project.com/Debugging#Tracing_Program_Execution > [1] git clone http://www.gnome.org/~gburt/git/mono-traces/ > [2] select sum(selfduration)/100 as ms, count(*) as calls, > class||':'||method as class_and_method from traces where > threadid=47328420921536 group by class, method order by ms desc limit > 25; > that threadid is what I determined was the main thread by looking at > the result of > select threadid, count(*) from traces group by threadid; > and picking out the thread with the most method calls. > _______________________________________________ > banshee-list mailing list > banshee-list gnome org > http://mail.gnome.org/mailman/listinfo/banshee-list -- Bertrand Lorentz <bertrand lorentz gmail com>
Attachment:
signature.asc
Description: This is a digitally signed message part