Re: [v8-users] Profiling v8 inside chromium/content_shell
Hi, as you have correctly observed, the timeline plot only takes those callbacks into account that are done in a VMState scope: VMState changes to and from EXTERNAL are logged. Fast API calls, i.e. jitted ones, are therefore not logged. That is, unless you specify --log-timer-events, which causes V8 to compile runtime calls before and after those fast API calls to log those calls (unless things have changed recently. Just grep for "FLAG_log_timer_events"). The reason it's behind a flag is that it would distort runtime considerably. The plot script tries to accomodate for those distortions so that the plot result reasonably well in most cases. And you are right that the timeline tool doesn't offer any deep insight into DOM operations. Btw. the plot script works in Chrome as standalone page now: https://x20web.corp.google.com/~yangguo/profviz/profviz/profviz.html Regards, Yang On Wed, Jun 12, 2013 at 7:39 PM, Adam Klein wrote: > On Tue, Jun 11, 2013 at 2:38 AM, Kentaro Hara > wrote: > >> Also, I'm a bit surprised at the way the v8 DOM callbacks end up in > >> the profile: those methods are usually trivial, with the real work > >> being somewhere deep in the core of Blink. Is it expected that only > >> the v8 entry point into Blink shows up when using the profiling tool? > > > > > > I've played around the V8 timeline tool, but it doesn't give us > reasonable > > data about DOM. In the timeline tool, DOM details (e.g. style > recalculation > > or layout) are not profiled. In addition, those heavy DOM operations can > be > > counted as a V8 execution time, because the timeline tool doesn't hook > entry > > points from JITted code (Only entry points from non-JITted code are > hooked). > > Yang will know more. > > Yang, can you explain this point a bit further? Does this mean that if > I see some DOM entry point taking, e.g., 10% of ticks I shouldn't > trust it at all? Or does it just mean that there's some stuff I'm > missing? > > > I've discussed how to improve the V8 timeline tool for DOM, but we found > > that it might be hard to extend it in a straightforward manner for some > > reasons. Thus, we started implementing another profiler based on trace > > events which will give you coarse-grained view about what percentages of > the > > main thread are changed on what (e.g. V8's GC, parsing, compiling, DOM > > attribute getters, style recalculation etc). I'm implementing the > profiler > > but it will take a bit more time to land it. > > > > > > > > On Tue, Jun 11, 2013 at 6:15 PM, Jochen Eisinger > > wrote: > >> > >> +kentaro for some profiling insights > >> > >> > >> On Tue, Jun 11, 2013 at 7:24 AM, Adam Klein wrote: > >>> > >>> I'm trying to profile the v8 execution of a web app using Chromium's > >>> content_shell with some success. But I'm also getting some odd > >>> results. I'm using a commandline like: > >>> > >>> content_shell --no-sandbox --js-flags='--prof --noprof-lazy > >>> --log-timer-events' http://localhost:8000/mypage > >>> > >>> And then processing the v8.log with > >>> > >>> v8/tools/linux-tick-processor v8.log > >>> > >>> The resulting profile has some quirks: none of the "JavaScript" > >>> portion of the profile lists more than 0.2% of the total ticks (even > >>> though there's >500ms of JS execution time as part of the app, as > >>> shown by both plot-timer-events and the Inspector's timeline). The C++ > >>> stack, meanwhile, has several major points of interest. Most of the > >>> big ones are Blink C++ callbacks (e.g., > >>> NodeV8Internal::dispatchEventMethodCallback), and __pthread_cond_wait > >>> shows up. But the top one is "__write", usually taking >30% of the > >>> ticks. > >>> > >>> If I go down to the call stacks, I get a bunch of "LazyCompile > >>> someMethod" entries which terminate at __write, so it seems I'm still > >>> getting some idea of which JS is taking the time, but I'm rather > >>> surprised that __write is the endpoint (it's mostly DOM tree > >>> walking/manipulation). Is this expected? > >>> > >>> Also, I'm a bit surprised at the way the v8 DOM callbacks end up in > >>> the profile: those methods are usually trivial, with the real work > >>> being somewhere deep in the core of Blink. Is it expected that only > >>> the v8 entry point into Blink shows up when using the profiling tool? > >>> > >>> Any insights would be valuable. > >>> > >>> Thanks, > >>> Adam > >>> > >>> -- > >>> -- > >>> v8-users mailing list > >>> v8-users@googlegroups.com > >>> http://groups.google.com/group/v8-users > >>> --- > >>> You received this message because you are subscribed to the Google > Groups > >>> "v8-users" group. > >>> To unsubscribe from this group and stop receiving emails from it, send > an > >>> email to v8-users+unsubscr...@googlegroups.com. > >>> For more options, visit https://groups.google.com/groups/opt_out. > >>> > >>> > >> > > > > > > > > -- > > Kentaro Hara, Tokyo, Japan > -- -- v8-users mailing list v8-users@googlegroups.com http://groups.google.com/grou
Re: [v8-users] Profiling v8 inside chromium/content_shell
On Tue, Jun 11, 2013 at 2:38 AM, Kentaro Hara wrote: >> Also, I'm a bit surprised at the way the v8 DOM callbacks end up in >> the profile: those methods are usually trivial, with the real work >> being somewhere deep in the core of Blink. Is it expected that only >> the v8 entry point into Blink shows up when using the profiling tool? > > > I've played around the V8 timeline tool, but it doesn't give us reasonable > data about DOM. In the timeline tool, DOM details (e.g. style recalculation > or layout) are not profiled. In addition, those heavy DOM operations can be > counted as a V8 execution time, because the timeline tool doesn't hook entry > points from JITted code (Only entry points from non-JITted code are hooked). > Yang will know more. Yang, can you explain this point a bit further? Does this mean that if I see some DOM entry point taking, e.g., 10% of ticks I shouldn't trust it at all? Or does it just mean that there's some stuff I'm missing? > I've discussed how to improve the V8 timeline tool for DOM, but we found > that it might be hard to extend it in a straightforward manner for some > reasons. Thus, we started implementing another profiler based on trace > events which will give you coarse-grained view about what percentages of the > main thread are changed on what (e.g. V8's GC, parsing, compiling, DOM > attribute getters, style recalculation etc). I'm implementing the profiler > but it will take a bit more time to land it. > > > > On Tue, Jun 11, 2013 at 6:15 PM, Jochen Eisinger > wrote: >> >> +kentaro for some profiling insights >> >> >> On Tue, Jun 11, 2013 at 7:24 AM, Adam Klein wrote: >>> >>> I'm trying to profile the v8 execution of a web app using Chromium's >>> content_shell with some success. But I'm also getting some odd >>> results. I'm using a commandline like: >>> >>> content_shell --no-sandbox --js-flags='--prof --noprof-lazy >>> --log-timer-events' http://localhost:8000/mypage >>> >>> And then processing the v8.log with >>> >>> v8/tools/linux-tick-processor v8.log >>> >>> The resulting profile has some quirks: none of the "JavaScript" >>> portion of the profile lists more than 0.2% of the total ticks (even >>> though there's >500ms of JS execution time as part of the app, as >>> shown by both plot-timer-events and the Inspector's timeline). The C++ >>> stack, meanwhile, has several major points of interest. Most of the >>> big ones are Blink C++ callbacks (e.g., >>> NodeV8Internal::dispatchEventMethodCallback), and __pthread_cond_wait >>> shows up. But the top one is "__write", usually taking >30% of the >>> ticks. >>> >>> If I go down to the call stacks, I get a bunch of "LazyCompile >>> someMethod" entries which terminate at __write, so it seems I'm still >>> getting some idea of which JS is taking the time, but I'm rather >>> surprised that __write is the endpoint (it's mostly DOM tree >>> walking/manipulation). Is this expected? >>> >>> Also, I'm a bit surprised at the way the v8 DOM callbacks end up in >>> the profile: those methods are usually trivial, with the real work >>> being somewhere deep in the core of Blink. Is it expected that only >>> the v8 entry point into Blink shows up when using the profiling tool? >>> >>> Any insights would be valuable. >>> >>> Thanks, >>> Adam >>> >>> -- >>> -- >>> v8-users mailing list >>> v8-users@googlegroups.com >>> http://groups.google.com/group/v8-users >>> --- >>> You received this message because you are subscribed to the Google Groups >>> "v8-users" group. >>> To unsubscribe from this group and stop receiving emails from it, send an >>> email to v8-users+unsubscr...@googlegroups.com. >>> For more options, visit https://groups.google.com/groups/opt_out. >>> >>> >> > > > > -- > Kentaro Hara, Tokyo, Japan -- -- v8-users mailing list v8-users@googlegroups.com http://groups.google.com/group/v8-users --- You received this message because you are subscribed to the Google Groups "v8-users" group. To unsubscribe from this group and stop receiving emails from it, send an email to v8-users+unsubscr...@googlegroups.com. For more options, visit https://groups.google.com/groups/opt_out.
Re: [v8-users] Profiling v8 inside chromium/content_shell
On Tue, Jun 11, 2013 at 7:24 AM, Adam Klein wrote: > I'm trying to profile the v8 execution of a web app using Chromium's > content_shell with some success. But I'm also getting some odd > results. I'm using a commandline like: > > content_shell --no-sandbox --js-flags='--prof --noprof-lazy > --log-timer-events' http://localhost:8000/mypage > > And then processing the v8.log with > > v8/tools/linux-tick-processor v8.log > > The resulting profile has some quirks: none of the "JavaScript" > portion of the profile lists more than 0.2% of the total ticks (even > though there's >500ms of JS execution time as part of the app, as > shown by both plot-timer-events and the Inspector's timeline). The C++ > stack, meanwhile, has several major points of interest. Most of the > big ones are Blink C++ callbacks (e.g., > NodeV8Internal::dispatchEventMethodCallback), and __pthread_cond_wait > shows up. But the top one is "__write", usually taking >30% of the > ticks. That's the write(2) libc wrapper, right? It sounds like your application or V8 is either doing a lot of writes (`strace -c` or perf should be able to confirm that) or some of them end up blocking for periods of times. The profiler is sampling-based. Sleeping in a system call will skew the numbers. > If I go down to the call stacks, I get a bunch of "LazyCompile > someMethod" entries which terminate at __write, so it seems I'm still > getting some idea of which JS is taking the time, but I'm rather > surprised that __write is the endpoint (it's mostly DOM tree > walking/manipulation). Is this expected? > > Also, I'm a bit surprised at the way the v8 DOM callbacks end up in > the profile: those methods are usually trivial, with the real work > being somewhere deep in the core of Blink. Is it expected that only > the v8 entry point into Blink shows up when using the profiling tool? It sounds like either functions are getting inlined or content_shell doesn't contain symbols. (Everything linked statically with -fvisibility=hidden, perhaps?) The tick processor uses nm(1) to match addresses to symbols. Maybe check its output to see if the symbols you expect to see are actually in there. > Any insights would be valuable. > > Thanks, > Adam -- -- v8-users mailing list v8-users@googlegroups.com http://groups.google.com/group/v8-users --- You received this message because you are subscribed to the Google Groups "v8-users" group. To unsubscribe from this group and stop receiving emails from it, send an email to v8-users+unsubscr...@googlegroups.com. For more options, visit https://groups.google.com/groups/opt_out.
Re: [v8-users] Profiling v8 inside chromium/content_shell
> > Also, I'm a bit surprised at the way the v8 DOM callbacks end up in > the profile: those methods are usually trivial, with the real work > being somewhere deep in the core of Blink. Is it expected that only > the v8 entry point into Blink shows up when using the profiling tool? I've played around the V8 timeline tool, but it doesn't give us reasonable data about DOM. In the timeline tool, DOM details (e.g. style recalculation or layout) are not profiled. In addition, those heavy DOM operations can be counted as a V8 execution time, because the timeline tool doesn't hook entry points from JITted code (Only entry points from non-JITted code are hooked). Yang will know more. I've discussed how to improve the V8 timeline tool for DOM, but we found that it might be hard to extend it in a straightforward manner for some reasons. Thus, we started implementing another profiler based on trace events which will give you coarse-grained view about what percentages of the main thread are changed on what (e.g. V8's GC, parsing, compiling, DOM attribute getters, style recalculation etc). I'm implementing the profiler but it will take a bit more time to land it. On Tue, Jun 11, 2013 at 6:15 PM, Jochen Eisinger wrote: > +kentaro for some profiling insights > > > On Tue, Jun 11, 2013 at 7:24 AM, Adam Klein wrote: > >> I'm trying to profile the v8 execution of a web app using Chromium's >> content_shell with some success. But I'm also getting some odd >> results. I'm using a commandline like: >> >> content_shell --no-sandbox --js-flags='--prof --noprof-lazy >> --log-timer-events' http://localhost:8000/mypage >> >> And then processing the v8.log with >> >> v8/tools/linux-tick-processor v8.log >> >> The resulting profile has some quirks: none of the "JavaScript" >> portion of the profile lists more than 0.2% of the total ticks (even >> though there's >500ms of JS execution time as part of the app, as >> shown by both plot-timer-events and the Inspector's timeline). The C++ >> stack, meanwhile, has several major points of interest. Most of the >> big ones are Blink C++ callbacks (e.g., >> NodeV8Internal::dispatchEventMethodCallback), and __pthread_cond_wait >> shows up. But the top one is "__write", usually taking >30% of the >> ticks. >> >> If I go down to the call stacks, I get a bunch of "LazyCompile >> someMethod" entries which terminate at __write, so it seems I'm still >> getting some idea of which JS is taking the time, but I'm rather >> surprised that __write is the endpoint (it's mostly DOM tree >> walking/manipulation). Is this expected? >> >> Also, I'm a bit surprised at the way the v8 DOM callbacks end up in >> the profile: those methods are usually trivial, with the real work >> being somewhere deep in the core of Blink. Is it expected that only >> the v8 entry point into Blink shows up when using the profiling tool? >> >> Any insights would be valuable. >> >> Thanks, >> Adam >> >> -- >> -- >> v8-users mailing list >> v8-users@googlegroups.com >> http://groups.google.com/group/v8-users >> --- >> You received this message because you are subscribed to the Google Groups >> "v8-users" group. >> To unsubscribe from this group and stop receiving emails from it, send an >> email to v8-users+unsubscr...@googlegroups.com. >> For more options, visit https://groups.google.com/groups/opt_out. >> >> >> > -- Kentaro Hara, Tokyo, Japan -- -- v8-users mailing list v8-users@googlegroups.com http://groups.google.com/group/v8-users --- You received this message because you are subscribed to the Google Groups "v8-users" group. To unsubscribe from this group and stop receiving emails from it, send an email to v8-users+unsubscr...@googlegroups.com. For more options, visit https://groups.google.com/groups/opt_out.
Re: [v8-users] Profiling v8 inside chromium/content_shell
+kentaro for some profiling insights On Tue, Jun 11, 2013 at 7:24 AM, Adam Klein wrote: > I'm trying to profile the v8 execution of a web app using Chromium's > content_shell with some success. But I'm also getting some odd > results. I'm using a commandline like: > > content_shell --no-sandbox --js-flags='--prof --noprof-lazy > --log-timer-events' http://localhost:8000/mypage > > And then processing the v8.log with > > v8/tools/linux-tick-processor v8.log > > The resulting profile has some quirks: none of the "JavaScript" > portion of the profile lists more than 0.2% of the total ticks (even > though there's >500ms of JS execution time as part of the app, as > shown by both plot-timer-events and the Inspector's timeline). The C++ > stack, meanwhile, has several major points of interest. Most of the > big ones are Blink C++ callbacks (e.g., > NodeV8Internal::dispatchEventMethodCallback), and __pthread_cond_wait > shows up. But the top one is "__write", usually taking >30% of the > ticks. > > If I go down to the call stacks, I get a bunch of "LazyCompile > someMethod" entries which terminate at __write, so it seems I'm still > getting some idea of which JS is taking the time, but I'm rather > surprised that __write is the endpoint (it's mostly DOM tree > walking/manipulation). Is this expected? > > Also, I'm a bit surprised at the way the v8 DOM callbacks end up in > the profile: those methods are usually trivial, with the real work > being somewhere deep in the core of Blink. Is it expected that only > the v8 entry point into Blink shows up when using the profiling tool? > > Any insights would be valuable. > > Thanks, > Adam > > -- > -- > v8-users mailing list > v8-users@googlegroups.com > http://groups.google.com/group/v8-users > --- > You received this message because you are subscribed to the Google Groups > "v8-users" group. > To unsubscribe from this group and stop receiving emails from it, send an > email to v8-users+unsubscr...@googlegroups.com. > For more options, visit https://groups.google.com/groups/opt_out. > > > -- -- v8-users mailing list v8-users@googlegroups.com http://groups.google.com/group/v8-users --- You received this message because you are subscribed to the Google Groups "v8-users" group. To unsubscribe from this group and stop receiving emails from it, send an email to v8-users+unsubscr...@googlegroups.com. For more options, visit https://groups.google.com/groups/opt_out.
