Help me interpret profiler output

One of the runs seems to have a call to LexerRuby::RubyLexer#initialize
that isn't in the others. Helps?

···

-----Original Message-----
From: Simon Strandgaard [mailto:neoneye@adslhome.dk]
Sent: Monday, 2 August 2004 3:26 PM
To: ruby-talk ML
Subject: help me interpret profiler output

Im randomly experiencing a big slowdown in my code.. but I fail see
where and what is causing this slowdown. Advices on how to move on are
appreciated.

Im writing a text editor which can do syntax colorering of Ruby code.
recomputing all 50 lines takes about 0.09 - 0.15 seconds.

However when inserting one letter.. so that only one line is recomputed,
then it takes between 0.03 - 0.43 seconds! Im interested in hunting
down
why it often spends so long time computing just a single line.

I have
1) profiled the recomputing of all 50 lines and
2) profiled the recomputing of a single line when speed is bad and
3) profiled the recomputing of a single line when speed is good.

when I compare the profiler output, I fail to see where the slowdown
are.

You may see the output here:
http://aeditor.rubyforge.org/wiki/wiki.pl?ProfilingLexerNew

The place where I recompute is in the method #sync_lcache in this file
http://rubyforge.org/cgi-bin/viewcvs/cgi/viewcvs.cgi/projects/experiment
al/buffer/source/buffer.rb?rev=1.2.2.11&cvsroot=aeditor&only_with_tag=b2
0040707&content-type=text/vnd.viewcvs-markup

I have inserted the following code around the place where I recompute

Profiler__.start_profile
# code to profile
Profiler__.stop_profile
Profiler__.print_profile(STDOUT)

If you have any ideas why the recomputation of a single line
takes unnecessary long time.. then please contact me.

How can I identify what sometimes is causing this slowdown?

--
Simon Strandgaard

not really.. the profiler output on that page are partial.. I left out the
bottom lines.

David Ross gave me a clue, to track keep track of time.. the recomputation of
one dirty line takes only to take 0.0027 seconds.. however at some point
afterwards something is eating time.. so it in total spends 0.15 seconds.
Hmm...

Eliminating console output doesn't change the situation (I have tried that).

Thanks Assaph for your suggestion.

···

On Monday 02 August 2004 08:22, Mehr, Assaph (Assaph) wrote:

One of the runs seems to have a call to LexerRuby::RubyLexer#initialize
that isn't in the others. Helps?

--
Simon Strandgaard

"Simon Strandgaard" <neoneye@adslhome.dk> schrieb im Newsbeitrag
news:200408021159.20045.neoneye@adslhome.dk...

> One of the runs seems to have a call to

LexerRuby::RubyLexer#initialize

> that isn't in the others. Helps?

not really.. the profiler output on that page are partial.. I left out

the

bottom lines.

David Ross gave me a clue, to track keep track of time.. the

recomputation of

one dirty line takes only to take 0.0027 seconds.. however at some point
afterwards something is eating time.. so it in total spends 0.15

seconds.

Hmm...

GC?

    robert

···

On Monday 02 August 2004 08:22, Mehr, Assaph (Assaph) wrote:

That is a possibility which I havn't thought about (me has unlearned too much
on my 3 week vacation).

How can I check if GC is running?

···

On Monday 02 August 2004 10:21, Robert Klemme wrote:

> Hmm...

GC?

    robert

--
Simon Strandgaard

"Simon Strandgaard" <neoneye@adslhome.dk> schrieb im Newsbeitrag
news:200408021221.12317.neoneye@adslhome.dk...

> > Hmm...
>
> GC?
>
> robert

That is a possibility which I havn't thought about (me has unlearned too

much

···

On Monday 02 August 2004 10:21, Robert Klemme wrote:
on my 3 week vacation).

How can I check if GC is running?

--
Simon Strandgaard

"Simon Strandgaard" <neoneye@adslhome.dk> schrieb im Newsbeitrag
news:200408021221.12317.neoneye@adslhome.dk...

> > Hmm...
>
> GC?
>
> robert

That is a possibility which I havn't thought about (me has unlearned too

much

on my 3 week vacation).

How can I check if GC is running?

Dunno, but you can switch it off and on: GC#disable and GC#enable .

    robert

···

On Monday 02 August 2004 10:21, Robert Klemme wrote:

I have added a GC.disable before I enter the critical area..
and after leaving the area I do a GC.enable.
Now the timing is much more consistent.

If I don't do so, then GC begin cleaning up and causes that
the operation often takes 100 miliseconds extra.

Thansk for your suggestion.. It helped.

···

On Monday 02 August 2004 11:56, Robert Klemme wrote:

--
Simon Strandgaard