Task tracer

[Thinker K.F. Li]

Hi all,

So many times, I have heard people do not understand why scrolling is so
slow, animation is not smooth. Gecko is so async that so many runnables
are post over numerous threads, so it is very hard to trace how b2g
spend the time for events. Events are timer, input events, network
messages.

We are working on a tool to help people to correlate runnables spread
over threads and processes (b2g & content process). The basic idea is
to give every runnable an unique ID, all runnables created by a runnable
share the same unique ID. Only the runnables created by events from
kernel/platform; e.g. input event, timer, network, sensors, ..., would
be assigned a new unique ID. So we can correlate all runnables
according unique IDs to understand the tracks of events.

The runnables created by events are origins. For example an input event
post a runnable on the main thread, that runnable is the origin of the
event. The origin gets a new unique ID. The origin may create a series
of more runanbles, they all share the same ID. By recording timestamp
for equeuing, dequeuing, and completion of runnables, and the unqiue
IDs, we can study how b2g spend the time and latency between threads for
events.

The unique IDs would be passed over IPC, so we can trace runnables
passed among processes. Some more information can be attached with the
unique IDs. But we would like to start by simple, so I don't mention
details here.

Cervantes, and others, and I will start to make a prototype.
Any feedback is welcomed!

--
Sinker
--
天教懶漫帶疏狂

[Ben Kelly]

On 08/23/2013 11:29 AM, Thinker K.F. Li wrote:
> We are working on a tool to help people to correlate runnables spread
> over threads and processes (b2g & content process). The basic idea is
> to give every runnable an unique ID, all runnables created by a runnable
> share the same unique ID. Only the runnables created by events from
> kernel/platform; e.g. input event, timer, network, sensors, ..., would
> be assigned a new unique ID. So we can correlate all runnables
> according unique IDs to understand the tracks of events.
>
> The runnables created by events are origins. For example an input event
> post a runnable on the main thread, that runnable is the origin of the
> event. The origin gets a new unique ID. The origin may create a series
> of more runanbles, they all share the same ID. By recording timestamp
> for equeuing, dequeuing, and completion of runnables, and the unqiue
> IDs, we can study how b2g spend the time and latency between threads for
> events.
>
> The unique IDs would be passed over IPC, so we can trace runnables
> passed among processes. Some more information can be attached with the
> unique IDs. But we would like to start by simple, so I don't mention
> details here.

This sounds like a great tool!

I'm curious if you have any idea about how much overhead this will add?
It sounds like it won't be bad. Are you planning to make it always on
or require a compile flag?

Also, how do you see us getting the data out? I assume the next problem
to solve will be visualizing the data usefully.

Finally, do you have a bug number for tracking this work? I'd like to
follow along on CC.

Thanks!

Ben

["平田修樹 (Naoki Hirata)"]

I would also like to follow along with the idea, as this may help QA
with finding more critical bugs and help Dev reduce time in
troubleshooting where the issue lies.

What is the bug number?

Regards,
Naoki

> _______________________________________________
> dev-b2g mailing list
> dev...@lists.mozilla.org
> https://lists.mozilla.org/listinfo/dev-b2g

[Shih-Chiang Chien]

This tool sounds great!
Could we integrate into Cleopatra so that we can find out the relationship between CPU usage and the event processing delay?

Best Regards,
Shih-Chiang Chien
Mozilla Taiwan

[Thinker K.F. Li]

For the overhead, I am not really sure, but, by my previous experiences,
it is not obviously. In additionally, by using TSC provided by CPU, the
overhead is comprised by register reading and some memory reading and
writing. It is a fixed overhead for every posted runnable. Comparing
to the runnable itself, it should be a minor part.

I think it should be enabled by a flag, at least at beginning.

The data would be in text format that can be hanled by grep, awk, sort,
... etc. For long term, we need to visualize the data. But, for now,
the infrastructures for tracing is more important than visualizing.
Maybe some others who is better on visualizing will do it.

It is bug 908995.

--
Sinker
--
天教懶漫帶疏狂

[Kevin Hu]

Thinker, thanks!

This sounds really cool. As far as I know, we can enable profiling to track some status(or maybe for performance issues). Will this be included in the profiling? And, will we have any Wiki page for this? :)


Thanks.
Kevin Hu

On Aug 24, 2013, at 6:15 PM, Thinker K.F. Li wrote:

> For the overhead, I am not really sure, but, by my previous experiences,
> it is not obviously. In additionally, by using TSC provided by CPU, the
> overhead is comprised by register reading and some memory reading and
> writing. It is a fixed overhead for every posted runnable. Comparing
> to the runnable itself, it should be a minor part.
>
> I think it should be enabled by a flag, at least at beginning.
>
> The data would be in text format that can be hanled by grep, awk, sort,
> ... etc. For long term, we need to visualize the data. But, for now,
> the infrastructures for tracing is more important than visualizing.
> Maybe some others who is better on visualizing will do it.
>
> It is bug 908995.
>
> Ben Kelly <bke...@mozilla.com> writes:
>

> --
> Sinker
> --
> 天教懶漫帶疏狂

[Thinker K.F. Li]

It would be integrated to cleopatra eventually, but plain text log is
with higher priority. There is no wiki page now. We will do that
before we are ready to roll it out.

From: Kevin Hu <k...@mozilla.com>
Subject: Re: [b2g] Task tracer
Date: Sat, 7 Sep 2013 09:50:56 +0800

> Thinker, thanks!
>
> This sounds really cool. As far as I know, we can enable profiling to track some status(or maybe for performance issues). Will this be included in the profiling? And, will we have any Wiki page for this? :)
>
>
> Thanks.
> Kevin Hu
>
> On Aug 24, 2013, at 6:15 PM, Thinker K.F. Li wrote:
>
>> For the overhead, I am not really sure, but, by my previous experiences,
>> it is not obviously. In additionally, by using TSC provided by CPU, the
>> overhead is comprised by register reading and some memory reading and
>> writing. It is a fixed overhead for every posted runnable. Comparing
>> to the runnable itself, it should be a minor part.
>>
>> I think it should be enabled by a flag, at least at beginning.
>>
>> The data would be in text format that can be hanled by grep, awk, sort,
>> ... etc. For long term, we need to visualize the data. But, for now,
>> the infrastructures for tracing is more important than visualizing.
>> Maybe some others who is better on visualizing will do it.
>>
>> It is bug 908995.
>>
>> Ben Kelly <bke...@mozilla.com> writes:
>>

[Jonas Sicking]

This sounds like something you should post to dev-platform as well.

Are you talking about doing this for just the runnables involved in
IPC handling, or for *all* implementations runnables posted to
threads?

One thing to note is that runnables aren't only used for asynchronous
events. One counterexample is

http://mxr.mozilla.org/mozilla-central/source/content/base/public/nsContentUtils.h?rev=33ec0e812f3b#1485

so we probably don't need need this for all nsIRunnables, but indeed
most of them.

/ Jonas

On Fri, Aug 23, 2013 at 8:29 AM, Thinker K.F. Li <thi...@codemud.net> wrote:
> Hi all,
>
> So many times, I have heard people do not understand why scrolling is so
> slow, animation is not smooth. Gecko is so async that so many runnables
> are post over numerous threads, so it is very hard to trace how b2g
> spend the time for events. Events are timer, input events, network
> messages.
>

> We are working on a tool to help people to correlate runnables spread
> over threads and processes (b2g & content process). The basic idea is
> to give every runnable an unique ID, all runnables created by a runnable
> share the same unique ID. Only the runnables created by events from
> kernel/platform; e.g. input event, timer, network, sensors, ..., would
> be assigned a new unique ID. So we can correlate all runnables
> according unique IDs to understand the tracks of events.
>
> The runnables created by events are origins. For example an input event
> post a runnable on the main thread, that runnable is the origin of the
> event. The origin gets a new unique ID. The origin may create a series
> of more runanbles, they all share the same ID. By recording timestamp
> for equeuing, dequeuing, and completion of runnables, and the unqiue
> IDs, we can study how b2g spend the time and latency between threads for
> events.
>
> The unique IDs would be passed over IPC, so we can trace runnables
> passed among processes. Some more information can be attached with the
> unique IDs. But we would like to start by simple, so I don't mention
> details here.
>

> Cervantes, and others, and I will start to make a prototype.
> Any feedback is welcomed!
>

[Thinker K.F. Li]

It is for all runnables of b2g and content processes. It includes
some changes of IPC to pass information among processes allowing
correlation of runnables of different processes.

From: Jonas Sicking <jo...@sicking.cc>
Subject: Re: [b2g] Task tracer

[Jonas Sicking]

Very cool!

Definitely something you should bring up on dev-platform, if you
haven't already, since it sounds like a pretty big change to gecko.

But it definitely sounds like a really cool idea!

/ Jonas