[erlang-questions] erlang:exit/1 eats lots of CPU time

[Maxim Treskin]

TOP 5 from total analyse:

Total time: 15.98
Measurement overhead: 0.89
FUNCTION                                       CALLS      TIME
erlang:exit/1                                  50         80 %
megaco_text_scanner:safe_chars/5               2792       1 %
log_server_core:process_message/3              929        1 %
gen_server:do_cast/2                           1008       1 %
log:log/6                                      929        0 %

where log_server_core and log is our internal modules.

TOP 30 exits from complete eprof log-file:

[zert@REDACTED]:/tmp $>> grep 'erlang:exit' pa_megaco-eprof.log | awk
'{print $3, "%\t", $1}' | sort -nr | head -n 30
100 %    erlang:exit/1
100 %    erlang:exit/1
99 %     erlang:exit/1
99 %     erlang:exit/1
98 %     erlang:exit/1
98 %     erlang:exit/1
97 %     erlang:exit/1
96 %     erlang:exit/1
93 %     erlang:exit/1
91 %     erlang:exit/1
90 %     erlang:exit/1
81 %     erlang:exit/1
80 %     erlang:exit/1
79 %     erlang:exit/1
74 %     erlang:exit/1
61 %     erlang:exit/1
53 %     erlang:exit/1
52 %     erlang:exit/1
42 %     erlang:exit/1
16 %     erlang:exit/1
14 %     erlang:exit/1
12 %     erlang:exit/1
11 %     erlang:exit/1
10 %     erlang:exit/1
9 %      erlang:exit/1
8 %      erlang:exit/1
8 %      erlang:exit/1
7 %      erlang:exit/1
6 %      erlang:exit/1
5 %      erlang:exit/1


2010/1/5 Mazen Harake <mazen.harake@REDACTED>:
> Hi,
>
> I think what Jayson is trying to say is:
>
> How long is "total CPU time"? 1 microsecond or 10 hours or somewhere in
> between?
>
> R,
> /M
>
> On 05/01/2010 14:04, Maxim Treskin wrote:
>>
>> Yes. This process consumes 12% of total CPU time. erlang:exit/1
>> consumes 99% of 12% of total CPU time. Whole system contains several
>> such processes which eats CPU on exit.
>>
>> 2010/1/5 Jayson Vantuyl<kagato@REDACTED>:
>>
>>>
>>> What's the total time here?  I see that erlang:exit/1 is 99% of that
>>> process's time, and that process is 12% of total time, but how long are we
>>> talking about here?  I've seen results like that for short tests in a tight
>>> loop.  So, it's 99% of 12% of what?
>>>
>>> On Jan 4, 2010, at 10:02 PM, Maxim Treskin wrote:
>>>
>>>
>>>>
>>>> Hello
>>>>
>>>> I have tested software with Eprof. eprof:analyse() prints log which
>>>> contains following strings:
>>>>
>>>> ****** Process<0.229.0>      -- 12 % of profiled time ***
>>>> erlang:exit/1                                  1          99 %
>>>>
>>>> Erlang node whith this process really eats CPU time, so it is not a
>>>> some bug of eprof. May be it is due to garbage collection of process
>>>> data on exit? Increasing of min_heap_size up to value which really
>>>> used by process has no effect.
>>>>
>>>> How I can decrease CPU time consumption on exit for this process?
>>>>
>>>> Thank you
>>>>
>>>> --
>>>> Maxim Treskin
>>>>
>>>> ________________________________________________________________
>>>> erlang-questions mailing list. See http://www.erlang.org/faq.html
>>>> erlang-questions (at) erlang.org
>>>>
>>>>
>>>
>>>
>>
>>
>>
>
>



-- 
Maxim Treskin