so - i accidentally pushed some pending commits (i was pushing a specific
commit Id to fix  brand new b0rks that broke emotion... - but it seems git had
other ideas).

so i may as well explain what this lump of new code is...

you'll notice now with every eina log err you get a backtrace - yes. i turned
it on specifically because i believe the errs are close to useless without a bt
telling you how you got there. this bt is generated by using libunwind. i am
using libunwind because i found backtrace() from libc ended up doing dl magic
that ended up doing mallocs inside the backtrace func... and this meant that if
you used this bt func in a signal handler for example... and that sig handler
was inside a malloc etc. func. you deadlocked. HOORAY glibc! not
backtrace_symbols(), just plain backtrace() to get the pointers. grrrr. anyway.

the backtrace now looks kind of "not very human readable". that's because
backtrace_symbols() is also largely useless and doesn't give you line numbers
and often simply gives you nothing more than a filename and no functions (eg if
you are a shared lib it may only get you symbols in the binary not the libs
being used). so you may get these shiny new bt's. don't throw them out. they
are USEFUL. for example:

/usr/local/lib/libeina.so.1      0x7fdb6208dbf6 0x7fdb6206d000
/usr/local/lib/libeina.so.1      0x7fdb6208ef19 0x7fdb6206d000
/usr/local/lib/evas/modules/engines/gl_generic/v-1.14/module.so  0x7fdb4867b0c9 
0x7fdb4866e000
/usr/local/lib/libevas.so.1      0x7fdb61838dc4 0x7fdb617d9000
/usr/local/lib/libevas.so.1      0x7fdb6183c5e6 0x7fdb617d9000
/usr/local/lib/libelementary.so.1        0x7fdb62744e3a 0x7fdb624f1000
/usr/local/lib/libevas.so.1      0x7fdb618692c4 0x7fdb617d9000
/usr/local/lib/libevas.so.1      0x7fdb6186a885 0x7fdb617d9000
/usr/local/lib/libevas.so.1      0x7fdb6185ec70 0x7fdb617d9000
/usr/local/lib/libeo.so.1        0x7fdb60a83ef4 0x7fdb60a79000
/usr/local/lib/libelementary.so.1        0x7fdb6272e686 0x7fdb624f1000
/usr/local/lib/libeo.so.1        0x7fdb60a83ef4 0x7fdb60a79000
/usr/local/lib/libeo.so.1        0x7fdb60a7d31d 0x7fdb60a79000
/usr/local/lib/libelementary.so.1        0x7fdb627421f8 0x7fdb624f1000
/usr/local/lib/ecore_evas/engines/x/v-1.14/module.so     0x7fdb50f31209 
0x7fdb50f28000
/usr/local/lib/libecore.so.1     0x7fdb615ad565 0x7fdb615a0000
/usr/local/lib/libecore.so.1     0x7fdb615b4c99 0x7fdb615a0000
/usr/local/lib/libecore.so.1     0x7fdb615b4fb7 0x7fdb615a0000
/usr/local/bin/rage      0x407eb0 0x400000
/usr/local/bin/rage      0x4052bc 0x400000
/usr/lib/libc.so.6       0x7fdb5ef17800 0x7fdb5eef7000
/usr/local/bin/rage      0x405319 0x400000

i added a new tool that can demangle this into something human readable that
makes gdb look boring and useless in comparison. just "cat" the above into a
new tool: eina_btlog and you'll get prettiness:

                                       /usr/local/lib/libeina.so.1       |      
                  /home/raster/C/efl/src/lib/eina/eina_log.c             : 1875 
@ eina_log_print_cb_stderr()
                                       /usr/local/lib/libeina.so.1       |      
                  /home/raster/C/efl/src/lib/eina/eina_log.c             : 1272 
@ eina_log_print_unlocked()
/usr/local/lib/evas/modules/engines/gl_generic/v-1.14/module.so          | 
/home/raster/C/efl/src/modules/evas/engines/gl_generic/evas_engine.c          : 
1271 @ eng_image_cache_flush()
                                       /usr/local/lib/libevas.so.1       |      
    /home/raster/C/efl/src/../src/lib/evas/canvas/evas_canvas.eo.c       :  332 
@ evas_canvas_image_cache_flush()
                                       /usr/local/lib/libevas.so.1       |      
    /home/raster/C/efl/src/../src/lib/evas/canvas/evas_canvas.eo.c       : 1119 
@ evas_image_cache_flush()
                                       /usr/local/lib/libelementary.so.1 |      
                /home/raster/C/elementary/src/lib/elm_win.c              : 1832 
@ _elm_win_evas_object_smart_del()
                                       /usr/local/lib/libevas.so.1       |      
    /home/raster/C/efl/src/../src/lib/evas/canvas/evas_object_smart.eo.c :   88 
@ evas_obj_smart_del()
                                       /usr/local/lib/libevas.so.1       |      
           /home/raster/C/efl/src/lib/evas/canvas/evas_object_smart.c    : 1022 
@ evas_object_smart_del()
                                       /usr/local/lib/libevas.so.1       |      
           /home/raster/C/efl/src/lib/evas/canvas/evas_object_main.c     :  735 
@ _evas_object_eo_base_destructor()
                                       /usr/local/lib/libeo.so.1         |      
                    /home/raster/C/efl/src/lib/eo/eo_base.eo.c           :   34 
@ eo_destructor()
                                       /usr/local/lib/libelementary.so.1 |      
                /home/raster/C/elementary/src/lib/elm_widget.c           : 5469 
@ _elm_widget_eo_base_destructor()
                                       /usr/local/lib/libeo.so.1         |      
                    /home/raster/C/efl/src/lib/eo/eo_base.eo.c           :   34 
@ eo_destructor()
                                       /usr/local/lib/libeo.so.1         |      
                    /home/raster/C/efl/src/lib/eo/eo_private.h           :  223 
@ _eo_del_internal()
                                       /usr/local/lib/libelementary.so.1 |      
                /home/raster/C/elementary/src/lib/elm_win.c              : 1953 
@ _elm_win_delete_request()
           /usr/local/lib/ecore_evas/engines/x/v-1.14/module.so          |    
/home/raster/C/efl/src/modules/ecore_evas/engines/x/ecore_evas_x.c         : 
1646 @ _ecore_evas_x_event_window_delete_request()
                                       /usr/local/lib/libecore.so.1      |      
                 /home/raster/C/efl/src/lib/ecore/ecore_private.h        :  308 
@ _ecore_lock()
                                       /usr/local/lib/libecore.so.1      |      
                 /home/raster/C/efl/src/lib/ecore/ecore_main.c           : 1917 
@ _ecore_main_loop_iterate_internal()
                                       /usr/local/lib/libecore.so.1      |      
                 /home/raster/C/efl/src/lib/ecore/ecore_main.c           :  982 
@ ecore_main_loop_begin()
                                       /usr/local/bin/rage               |      
                      /home/raster/C/rage/src/bin/main.c                 :  142 
@ elm_main()
                                       /usr/local/bin/rage               |      
                      /home/raster/C/rage/src/bin/main.c                 :  145 
@ main()
                                             /usr/lib/libc.so.6          |      
                                               ??/??                     :  145 
@ __libc_start_main()
                                       /usr/local/bin/rage               |      
                                               ??/??                     :    0 
@ _start()

and unlike this email (where i have specifically avoided wrapping the above 
lines), you will ALSO get color hilighitng in a terminal so it looks a lot like:

  http://www.enlightenment.org/ss/e-554c47e04aa3c8.67314304.png

so now in efl we have a fairly useful backtracer that could be used anywhere.
there is an EINA_BT() macro which is defined if EINA_HAVE_DEBUG is defined
and it's in eina_debug.h - internal right now to eina, but perhaps in future
it can become "public". either way - an improvement on what we had before.
if you have eina log complaints, you now have a full usable backtrace to
where the complaint came from.

that brings me to the other new bits of code, which right now don't do much,
so people won't be affected, but i guess i should explain.

there is now efl_debugd and efl_debug as 2 tools. if efl_debugd is running
then ALL efl apps connect to it (it is per-user and setuid apps will refuse
to connect). efl_debugd is the start of a "debug management tool". the idea
is that it can sit around and know of every efl app, be able to talk to
efl apps and turn on debugging, fetch logs, information or profiling info
from all efl apps and store it or whatever. then other efl debug clients
(efl_debug is a cmdline client right now) can talk to this daemon and access
such information. for example we could have a gui debugger to dump memory
info from any running efl app, or begin profiling cpu usage per thread. in
fact there is code in the efl debug monitor to do exactly this. it can poll
at a "high frequency" and fetch backtraces from within an app across all
threads. this is meant to be the start of something that can be used to
probe into apps and figure out "why did my app skip a few frames?" or
"why is it pausing?" or "where is my cpu goaing in a general rough way?"
etc. etc. - the monitor launches a thread that sits in the bg and connects
to efl_debugd and then can accept commands and probe inside an app. the
profiling uses SIGPROF literally to walk across every thread with
pthread_kill() that thread and get a sig handler to run that dumps a bt
back to the monitor thread that picks it up. this does actually work and
i have seen the ability to grab up to 50,000 backtraces per second so far
without actually seeing the app visibly slow down (though it does end up
keeping an entire cpu core busy to do this). this is a big reason for using
libunwind because this signal handler ended up interrupting a lot of things
like malloc()s that ended up in deadlocks. it is also why the backtracer
code has custom memory handling that never uses malloc/free (uses mmap or
fixed compiled-in buffers if you dont have mmap + mmap anonymous).

for now if you run efl_debugd - everyone will connect next time they run.
you won't see much, but "efl_debug list" will connect and list all clients
by PID. at this point PID is provided by client as clients are trusted to
"play nice" as they all run as the same UID. I can add verification later
for this. but just remember - the only user who can access the debug daemon
is yourself. (well and root). so at this stage it's not a security issue.

you can also do "efl_debug pon PID 10" for example where PID is the pid of
the process to turn on profiling. 10 is the sleep time between polls of
backtraces. you can get the client to stop profiling again with
"efl_debug poff PID". this is all experiemental at this stage and just
shows this stuff is working. if you set the sleep time to 0 then profiling
will capture backtraces as fast as it possibly can. the client will dump
how many bt's per second it's managing to do to stdout.

if efl_debugd exits, any clients connected will disconnect and exit the
debug monitor thread. they will need to be re-run to connect to any new
debug daemon that is started.

so at this stage this is all raw infra for far better debugging in efl.
i hope to make this a more expandable info for things like clouseau to
hook into as "protocol extensions". that's a while down the road though.

before i get there i want to make an event log with the new debug infra.
what is this i hear you ask? i'd love to have a visual tool that can show
a timeline of a process and show every time it wakes in a scrollable
visual timeline with little bars and points indicating events or the begin
and end of some section of processing. show the reason for wakeup (animator
or i/o wakeup, or timer etc.), show when i/o collection begins in fd
handlers and when that ends, when event handlers begin being called, when
they end, how long each event handler takes (and what the function was),
when rendering begins and within this how long smart calcs take, and which
objects take how much time, how long rendering phases take etc. etc. etc.
and have an inspectable visual history log of all these things efl does
all day long so you can at least to a rough extent begin to find out where
your time is going and what is the blocker - is it some eet file i/o
stopping the mainloop? is it some event handler or callback eating up
most of your precious time? which one is it? which one was it during that
ONE hiccup where you skipped 3 frames and you can't easily "reproduce it"?
this kind of information i'd like to be extracting out of efl apps
"on the fly". with debugd we can turn ON event logging on a suspect app and
then it can accumulate a log locally (we could indicate the detail level
desired when turning it on), and then have efl_debugd regularly "snarf"
out the log (eg every 0.1 sec or something) which can clear the app local
log (freeing up memory on the app side) and letting debugd store it in ram
or a file and/or handing it off to another gui client to display in a
chart that live updates as you go. that is where i want to go with this
first. it will be a major boon for debugging efl apps from the wm through
to terminology and anything else. it will allow us to debug without having
to launch an aup under a debugger like gdb, valgrind etc. and without
unduly impacting performance of that app.

anyway - so that's what that code dump was about. wasn't "done" yet, but
it shouldn't affect anyone unless they start using these things (beyond
the new bt's on eina log outputs). it SHOULD only be enabled if the right
autofoo checks pass (so atm windows shouldnt work here - maybe not osx
or even bsd, but linuxes should). libunwind check is automagic atm as i
didn't want to make it a hard dep or force a --enable. it's early days.

of course feedback, patches, cheering, help working on it, or anything
else is welcomed. just keep in mind it's early and has a while to go.

-- 
------------- Codito, ergo sum - "I code, therefore I am" --------------
The Rasterman (Carsten Haitzler)    ras...@rasterman.com


------------------------------------------------------------------------------
One dashboard for servers and applications across Physical-Virtual-Cloud 
Widest out-of-the-box monitoring support with 50+ applications
Performance metrics, stats and reports that give you Actionable Insights
Deep dive visibility with transaction tracing using APM Insight.
http://ad.doubleclick.net/ddm/clk/290420510;117567292;y
_______________________________________________
enlightenment-devel mailing list
enlightenment-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/enlightenment-devel

Reply via email to