Page MenuHomePhabricator

Version 1.0.2
Updated 494 Days AgoPublic

EFL Profiling Viewer

Profiling Viewer - developer application for graphical view and analyze log-files, created by efl_debug. Main feature - visualization the program workflow. That is useful for debugging and "bottleneck" seeking. The Profiling Viewer provide elements for easy navigation through log-file and investigate any time interval.

Overview

Window contains two sections:


Top part contains info about time interval chosen by user. More detailed information could be find here: visualization of the logged events, their duration, CPU usage for every thread, CPU frequency for every core.
Bottom part related to whole log, it is a log-map that shows what happens from the beginning logging to the end. It shows information like CPU characteristic and threads activity represented as graphs.

Every part contains time marks, that shows approximate duration of events.

Mechanism of Intervals

Profiling Viewer does not store in memory full log-file, it stores only hints, that helps find data related to chosen interval quickly.
To achieve this goal it requires reading full log-file. Reading happens once after opening and needed for collect hints data. Each time when the requested display interval changed reads only data related to the new time interval.

Launch EFL Profiling Viewer

CLI

There is possibility to work with Profiling Viewer through command line.
Typing path to log-file opens this log immediate:

efl_profiling_viewer ~/efl_debug_evlog-2629.log

Also available few options for setting first interval:

efl_profiling_viewer --start=10 --duration = 5

This command shows interval from 10 to 15 second when any log opens at first. It is possible to add path to log-file after options.
To open full list of commands type

efl_profiling_viewer -h
Open

It is possible to open existing log-file from main menu FileOpen. Opening new log-file will close currently opened log.

Navigation

As app shows only one interval, it required tools for easy change time range to another. There are implemented few abilities that can be helpful.

  • Zoom: zoom in or zoom out on interesting place. Zoom performs by Ctrl+mouse wheel scroll
  • Navigation buttons: change interval to next or previous.
  • Log-map: Choose new area by mouse on log-map.
  • Event-zoom: double-click on event display interval of this event.
  • Dialog window: time range can be chosen directly from dialog window. ViewRange

Displaying

Timemark area contains timestamps and timelines that help for navigation and show event duration visually. Also, here placed navigation buttons for changing interval to next or previous.

CPU frequency area contains information about frequency on every core. Events have gradation from white(0) to red(maximum registered CPU frequency)

Frequency dependent from other apps, not only logged.

States area contains state events. Every unique state event name has own row. Click on event opens panel with more details.

Threads area contains CPU usage events, thread events and single events separated on threads. CPU event placed on top of every thread and like cpu frequency have gradation from white(idle) to red(highload). If usage = 0, this event wouldn't displayed.
Thread events in middle. Every unique name have own color so it`s easy to recognize them. Click on event opens panel with more details.
Single events placed in bottom part of threads. They also have unique colors for each name and can be clicked for more info.

All events have tool-tips.

NOTE: If event is too small in chosen zoom it will be displayed with small opaque. Few sequent transparent events are united in one big transparent rectangle. Zoom in to see more details.

Log-map contain graphs that shows changes of CPU usage and CPU frequency during log duration. It shows thread activity too: for each thread displayed intervals when exist at least one thread event. All this information is approximated.
In log-map also showed where in log placed chosen interval and here you can choose another one: just select it by mouse.
This area placed in panes, so it can be hidden if not required.

Add to your source code eina_evlog marks

For logging any event, call function eina_evlog() in source code. Full documentation about event types and using eina_evlog can be found here. But short description available below.

Thread events

Have "+" and "-" before name. "+event_name" means that event_name started, "-event_name" means that event_name finished.

For correct log displaying every started event must have finish.

These events related to their thread, so events with same name in different threads might exist. And you cannot start thread event in one thread and finish in another.

Single events

Their name starts from "!". Like thread event they are related to thread. Can be useful for logging instant events without start and finish.

State events

Beginning of state event name starts with ">" and end starts with "<". They are not related to any thread and would display in special area. Independence from thread make this type of events useful for logging global events.

CPU events

Collected automatically. Don't care about them.

Filters

Often logged data contain a huge amount of various events. For example look at the Evas rendering process log data. A set of the events are registered each time when frame going to be rendered. Let assume that average frame rate for profiled application more than 100 frames per second. Result will be the mass of the render related events will be displayed. This make visual investigation of logged data inconvenient. The natural way to decrease amount of the displayed events objects - using filters.
Filter dialog window available from ViewFilters or from the events area context menu. There are two columns. One with the rules list and the second one is the list of the events.

Current log
This item contain all event names that was logged. Turn event off in right list to ignore it. CPU events placed at top of list. Turn off frequency events to accelerate interval displaying if you don't need them.
Rules
IIt is the possible use case, when the same events are displayed in many logs. It could be logged data from different applications or even from the same application but from different runs. Good to have the same filtering status of events to be stored inside rules. Those rules could be applied during different profiling procedures.
Events could be added into rules by "+" button, that placed inside events group type name. Or using Drag&Drop mechanism. Drag event from already existed rule and drop event above the target rule name. For creating a new rule use "+" button. Also, possible to copy existing rule to new one. For that uses "Save as new rule" button. If few rules applied sequentially, then the last rules will have a bigger priority. Rule may contain events, that absent in log file: it can be useful, for applying one rule to log with different set of events.
New rules saves automatically in eet file inside the config directory. Saving done each time when Profiling Viewer app was closed normally.

Filters in "current log" have the highest priority.

Additional buttons

  • Save as new rule: clone existing rule to new rule. Also can be applied to current log. Useful if you need few similar rules.
  • Turn on all: turn on all events in current log or rule. Useful if you need to display all events except few.
  • Turn off all: turn off all events in current log or rule. Useful if you need to display only few specific events.
  • Redraw log: filtration applies only when next redrawing interval happens. This button applies filtration to current interval immediately.

Time range choose

To simplify way to selecting needed time range was added a special tool.


The selecting time range dialog could be find at menu ViewTime range. The dialog window contain set of spinner for selecting accurate time range.
Possible range, that could be selected is limited by range from 0 hours 0 min 0 sec till 23 hours 59 minutes 59 second 999 milliseconds 999 microseconds.

Examples

Loop difference

eina_evlog("+first loop", NULL, 0.0, NULL);
for (i = 0; i < 5; i++)
  sleep(1);
eina_evlog("-first loop", NULL, 0.0, NULL);
eina_evlog("!first loop ended", NULL, 0.0, NULL);

eina_evlog("+second loop", NULL, 0.0, NULL);
for (i = 0; i < 5 * 1000000000; i++);
eina_evlog("-second loop", NULL, 0.0, NULL);


Two thread events shows loops duration, single event show end of first loop. Also, easy to see, that since first CPU was in idle, but in second CPU usage become 100%.
Infinity loops
Let`s change first loop a little:

for (i = 0; i < 5; i++)
   {
     sleep(1);
     i--;
   }


Loop become infinitive and finish event wasn't logged. Unknown, will exist finish event in future or not, so this event not displayed.
But error message in single events line shows something went wrong.
Also, it can be helpful with unexpected long events.
Single and small events
Let`s try to log some short action.

if (i == 3)
  {
    eina_evlog("+action", NULL, 0.0, NULL);
    printf("Action!\n");
    eina_evlog("-action", NULL, 0.0, NULL);
  }

But it would be hard to find this event in profiler(small line before 4s). Now it will be useful add extra marks with single events:

eina_evlog("!action", NULL, 0.0, NULL);
eina_evlog("+action", NULL, 0.0, NULL);
printf("Action!\n");
eina_evlog("-action", NULL, 0.0, NULL);


Now it visible, what area required zoom.
Divide and conquer
Lets imagine, that on one iteration of loop was unexpected error.

if (i == 3)
 {
   eina_evlog("!ERR", NULL, 0.0, "error message");
 }


Error displayed, time known... But that`s all and more details required.
Good way - divide long event on few children, for example:

for (int i = 0; i < 5; i++)
   {
     eina_evlog("+first loop iteration", NULL, 0.0, NULL);
     if (i == 3)
       {
         eina_evlog("!ERR", NULL, 0.0, "error message");
       }
     sleep(1);
     eina_evlog("-first loop iteration", NULL, 0.0, NULL);
   }


Now clearly visible, that error happens on fourth iteration of loop. For more info divide more.
Child events
Now it is possible, when event, that started later ends later two.

eina_evlog("+first loop", NULL, 0.0, NULL);
   for (int i = 0; i < 5; i++)
   {
     eina_evlog("+first loop itteration", NULL, 0.0, NULL);
     if (i == 3)
       {
         eina_evlog("+child", NULL, 0.0, NULL);
       }
     sleep(1);
     eina_evlog("-first loop itteration", NULL, 0.0, NULL);
   }
   eina_evlog("-first loop", NULL, 0.0, NULL);
   sleep(1);
   eina_evlog("-child", NULL, 0.0, NULL);

NOTE: if new event starts after loop and before child event ends, it will be placed on first founded empty space.

Multithread visualization
Small example that shows in which order feedbacks from threads processed.

Few other features

ERR messages

Feature: single events that named as "!ERR", "!WRN", "!DBG", "!CRIT" would color in red.
How to use: log errors: it`s find your error messages and investigate their causes.

Feature: details about event can be logged.
How to use: differ ends of events. For example, log returned value of function.

Feature: thread events can be related to different objects.
How to use: events can have same name, if to eina_evlog() called with different objects and they would display as different events.

TODO list

Available here

Clouseau integration

It is more convenient to profile the application during runtime, than investigate early recorded log files.
For Enlightenment project was created a great tool #clouseau to have a complete debugging one-stop-shop tool for inspecting object trees and timeline execution and much more. From Profiling Viewer version 1.0.2 it is possible to usage with #clouseau as plugin.

Module

Into #clouseau source code tree was added profiling viewer module. commit link
In case if on time when #clouseau compilation process started the Profiling Viewer was installed into system - the specified module will be installed automatically.

Usage

The efl_debugd daemon should be launched firstly. It is necessary to enable efl debug infrastructure on.
After that the #clouseau could connect to the local daemon or remote. Need to chose needed type of connection. And select application from the drop down menu.


When #clouseau connected to the necessary application the Profiling Viewer could be chose from extensions list.
All features of Profiling Viewer tool available inside clouseau too. By the mouse right click anywhere on the profiling data the context menu with all features could be find.

Last Author
NikaWhite
Last Edited
Dec 14 2017, 1:23 AM
Projects
None
Subscribers
None