[Banshee-List] optimization research

[Gabriel Burt <gabriel burt gmail com>]

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.

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.