Re: Fast way to clear trace logs and continue tracing?

Re: Fast way to clear trace logs and continue tracing?

[Jonathan Rajotte Julien]

Hi Douglas,


On 2016-12-13 09:41 PM, Douglas Graham wrote:
> Hi,
>
> I just started working with lttng recently, so apologies if this is a dumb question.

Welcome!

>
> Suppose I have configured and started a session and have collected a bunch of traces in a trace file.  Now I want to clear those traces but then continue saving new traces using the same session.  Is there a reasonably fast way to do that?

Normally the typical use case is the other way around, you work in 
flight-recorder mode (not touching disk or network) and take "snapshot" 
when needed.

Could you explain what you want to achieve? What is the bigger picture?

>
> What we currently do is "lttng save --output-path=x.cfg; lttng stop; lttng destroy; rm -rf <tracedir>; lttng load --input-path=x.cfg

Are you saving/loading multiple sessions ? Probably not since you use 
"lttng stop" and "lttng destroy directly".

Still, using "lttng save --output-path=x.cfg" will create a directory 
"x.cfg" containing one to multiple sessions configurations.

"lttng load --input-path=x.cfg"  will look into the "x.cfg" folder and 
load all sessions configuration present.

If this is not the behavior you want make sure to give the name of the 
session to both commands.

You systematically remove the traces ? When does this get executed 
(cron, user action, trace size)?
When does the trace data become important? When do you want to keep the 
trace data?

Is it a requirement that the new session have the same name and/or the 
same output path?

>
> But this is very slow in some cases.  The lttng load in particular is extremely slow when Linux is running inside a virtual machine.

I will test that. Not sure what would cause the load command to be slow 
inside a vm particularly.
The " lttng stop" and "rm -rf" are most probably taking more time than 
the load command.

Could you give us more information regarding the configuration you are 
loading? Number of channels, enabled events, type of session (live, to 
disk, streaming).

>    I was hoping that lttng might support a "lttng clear" that could be used to remove all traces from the trace file, but I can't find any such command.

That is an interesting idea.

>
> I note that lttng does support the rotating of trace files when they reach a size limit.  I think that's fairly close to what I want.  If I could force a trace file rotation at an arbitrary time and then simple remove the old rotated log, leaving the new one, that seems like it should do the job.  Except I don't see any way to force a rotation.

Having a way to force a rotation would be something that would make 
sense. Mathieu Desnoyers/Jeremie Galarneau might be able to give more 
information on the feasibility of such a feature.

>
> Any ideas?
>
> Thanks,
> Doug

So far I do not see any dumb questions. :P

Cheers

> _______________________________________________
> lttng-dev mailing list
> lttng-dev@lists.lttng.org
> https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

-- 
Jonathan R. Julien
Efficios

_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: Fast way to clear trace logs and continue tracing?

[Jonathan Rajotte Julien]

Hi Douglas,

On 2016-12-14 02:47 PM, Douglas Graham wrote:
> Thanks for your reply Jonathan,
>
> I don't remember ever having this problem before.  I posted my question
> to lttng-dev without being subscribed, so I did not get your reply in an email.
> I'm pasting it from the archives into an email this time, but I've just sent a
> Subscription request so next time hopefully I won't have this problem.

Probably my error, Thunderbird have a "Reply to mailing list" button.

>
>>> Suppose I have configured and started a session and have collected
>>> a bunch of traces in a trace file.  Now I want to clear those
>>> traces but then continue saving new traces using the same session.
>>> Is there a reasonably fast way to do that?
>> Normally the typical use case is the other way around, you work in
>> flight-recorder mode (not touching disk or network) and take "snapshot"
>> when needed.
>>
>> Could you explain what you want to achieve? What is the bigger picture?
> We are using lttng as the backend to a legacy logging system that
> previously ran on an RTOS. Application code generates logs by calling
> routines that now map to lttng tracepoints. The commands that have
> historically been used to view and clear these logs, and which we want
> to remain the same, are:
>
>     log read
>     log clear
>
> It's that "log clear" command that is problematic with lttng.
> It gets used a lot in our automated testing where we want to view
> only the logs generated by a particular test. eg:
>
>   while have more tests to run
>     run test
>     log read  # the test engine captures the output from this command
>     log clear
>
> If we can't clear the logs between tests, then we have to dump
> the entire huge logfile after each test, and that can be slow and
> can cause other issues as well.

Seems like a fair use case.

>
>>> What we currently do is "lttng save --output-path=x.cfg; lttng stop;
>>>         lttng destroy; rm -rf <tracedir>; lttng load --input-path=x.cfg
>> Are you saving/loading multiple sessions ? Probably not since you use
>> "lttng stop" and "lttng destroy directly".
> All of these operations are performed on only one session,
> "xcs_trace". The session name is passed to the save, stop, and
> destroy commands.  I left if off to try to keep things brief (which
> might have been a bad idea).

It's alright, I just needed to make sure of it.

>   The contents of the xcs_trace.lttng
> file generated by the save command are at the end of this email.
>
>> You systematically remove the traces ? When does this get executed
>> (cron, user action, trace size)?
>> When does the trace data become important? When do you want to keep the
>> trace data?
> Hopefully, I've answered this above.  Our test engine use "log read" and "log clear"
> a lot, but these are also frequently used manually.  For example, a developer might
> boot up the system, which generates a lot of logs, but then clear those bootup logs
> so that any subsequent logs generated by manual testing are easier to get to without
> scrolling through thousands of lines of bootup logs.
>
>> Is it a requirement that the new session have the same name and/or the
>> same output path?
> Hmmm. I think the only real requirement is that any newly generated
> logs become visible via subsequent "log read" commands.  If we
> can do that with a different session name and/or output path,
> that would probably be sufficient.

Since the culprit seems to really be the load command the solution I had 
in mind does not apply here.

>
>>> But this is very slow in some cases.  The lttng load in particular is
>>> extremely slow when Linux is running inside a virtual machine.
>> I will test that. Not sure what would cause the load command to be slow
>> inside a vm particularly.
>> The " lttng stop" and "rm -rf" are most probably taking more time than
>> the load command.
> It's definitely the load command that is the killer in our
> environment.  I'd send you output from the time command, except that
> time inside our VM is pretty much meaningless because it's an event
> driven simulation where time runs fast when there is little to do
> and slow when there is lots to do.  This is an ARM instruction set
> simulator that does run fairly slowly on our x86_64 machines, but the
> "log clear" command stands out as running considerably more slowly
> than other commands, especially given that conceptually at least,
> it's not doing very much.  Overall, our existing implementation of
> "log clear" takes about 25 seconds, and 20 seconds of that (give
> or take) is from the lttng load command.

Big problem here. I'll take a look a how things get done in the load 
command.

Did you try replicating the session setup via the lttng command without 
using the load command?

I expect it the be pretty much the same performance in the end but it 
could be a base comparison.
It could also help identify the culprit, if any, inside the load command 
(file access, xml parsing, internal lttng communication, etc.) or the 
setup action responsible (create, enable-event, etc);

>
>> Could you give us more information regarding the configuration you are
>> loading? Number of channels, enabled events, type of session (live, to
>> disk, streaming).
> I hope the answers are all contained within the xcs_trace.lttng file included below.
>
>> So far I do not see any dumb questions. :P
> That's a relief :-)
>
> Here's the contents of xcs_trace.lttng, the file saved by the "lttng save"
> command:
>
> ======== begin xcs_trace.lttng ========
> <?xml version="1.0" encoding="UTF-8"?>
> <sessions>
>      <session>
>          <name>xcs_trace</name>
>          <shared_memory_path>/var/log/lttng/shm/current/xcs_trace-20000101-000000</shared_memory_path>
>          <domains>
>              <domain>
>                  <type>UST</type>
>                  <buffer_type>PER_UID</buffer_type>
>                  <channels>
>                      <channel>
>                          <name>ch1</name>
>                          <enabled>true</enabled>
>                          <overwrite_mode>OVERWRITE</overwrite_mode>
>                          <subbuffer_size>131072</subbuffer_size>
>                          <subbuffer_count>16</subbuffer_count>
>                          <switch_timer_interval>0</switch_timer_interval>
>                          <read_timer_interval>0</read_timer_interval>
>                          <output_type>MMAP</output_type>
>                          <tracefile_size>0</tracefile_size>
>                          <tracefile_count>0</tracefile_count>
>                          <live_timer_interval>0</live_timer_interval>
>                          <events>
>                              <event>
>                                  <name>*</name>
>                                  <enabled>true</enabled>
>                                  <type>TRACEPOINT</type>
>                                  <loglevel_type>RANGE</loglevel_type>
>                                  <loglevel>6</loglevel>
>                              </event>
>                              <event>
>                                  <name>com_ericsson_tri*</name>
>                                  <enabled>true</enabled>
>                                  <type>TRACEPOINT</type>
>                                  <loglevel_type>RANGE</loglevel_type>
>                                  <loglevel>14</loglevel>
>                              </event>
>                          </events>
>                          <contexts/>
>                      </channel>
>                  </channels>
>                  <trackers/>
>              </domain>
>              <domain>
>                  <type>JUL</type>
>                  <buffer_type>PER_UID</buffer_type>
>                  <channels/>
>              </domain>
>              <domain>
>                  <type>LOG4J</type>
>                  <buffer_type>PER_UID</buffer_type>
>                  <channels/>
>              </domain>
>              <domain>
>                  <type>PYTHON</type>
>                  <buffer_type>PER_UID</buffer_type>
>                  <channels/>
>              </domain>
>          </domains>
>          <started>true</started>
>          <attributes>
>              <snapshot_mode>true</snapshot_mode>
>          </attributes>
>          <output>
>              <snapshot_outputs>
>                  <output>
>                      <name>snapshot-1</name>
>                      <max_size>0</max_size>
>                      <consumer_output>
>                          <enabled>true</enabled>
>                          <destination>
>                              <path>/pramfs/log/lttng/snapshot</path>
>                          </destination>
>                      </consumer_output>
>                  </output>
>              </snapshot_outputs>
>          </output>
>      </session>
> </sessions>
> ========== end xcs_trace.lttng ==============

Since you are using a session in snapshot mode a "clear buffer" action 
could help your use case.

Allowing manual flushing of buffers for snapshot sessions might be 
something worth investigating.

Still the previous idea you had regarding the use of the trace file 
rotation feature triggered manually would fit better in the end.
You would be able to use a regular session to achieve the same result.

Cheers

>
> Regards,
> Doug
>
>
> _______________________________________________
> lttng-dev mailing list
> lttng-dev@lists.lttng.org
> https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

-- 
Jonathan R. Julien
Efficios

_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: Fast way to clear trace logs and continue tracing?

[Douglas Graham]

Thanks for your reply Jonathan,

I don't remember ever having this problem before.  I posted my question
to lttng-dev without being subscribed, so I did not get your reply in an email.
I'm pasting it from the archives into an email this time, but I've just sent a
Subscription request so next time hopefully I won't have this problem.

>> Suppose I have configured and started a session and have collected
>> a bunch of traces in a trace file.  Now I want to clear those
>> traces but then continue saving new traces using the same session.
>> Is there a reasonably fast way to do that?
>
> Normally the typical use case is the other way around, you work in
> flight-recorder mode (not touching disk or network) and take "snapshot"
> when needed.
>
> Could you explain what you want to achieve? What is the bigger picture?

We are using lttng as the backend to a legacy logging system that
previously ran on an RTOS. Application code generates logs by calling
routines that now map to lttng tracepoints. The commands that have
historically been used to view and clear these logs, and which we want
to remain the same, are:

   log read
   log clear

It's that "log clear" command that is problematic with lttng.
It gets used a lot in our automated testing where we want to view
only the logs generated by a particular test. eg:

 while have more tests to run
   run test
   log read  # the test engine captures the output from this command
   log clear

If we can't clear the logs between tests, then we have to dump
the entire huge logfile after each test, and that can be slow and
can cause other issues as well.

>> What we currently do is "lttng save --output-path=x.cfg; lttng stop;
>>        lttng destroy; rm -rf <tracedir>; lttng load --input-path=x.cfg

> Are you saving/loading multiple sessions ? Probably not since you use
> "lttng stop" and "lttng destroy directly".

All of these operations are performed on only one session,
"xcs_trace". The session name is passed to the save, stop, and
destroy commands.  I left if off to try to keep things brief (which
might have been a bad idea). The contents of the xcs_trace.lttng
file generated by the save command are at the end of this email.

> You systematically remove the traces ? When does this get executed
> (cron, user action, trace size)?
> When does the trace data become important? When do you want to keep the
> trace data?

Hopefully, I've answered this above.  Our test engine use "log read" and "log clear"
a lot, but these are also frequently used manually.  For example, a developer might
boot up the system, which generates a lot of logs, but then clear those bootup logs
so that any subsequent logs generated by manual testing are easier to get to without
scrolling through thousands of lines of bootup logs.

> Is it a requirement that the new session have the same name and/or the
> same output path?

Hmmm. I think the only real requirement is that any newly generated
logs become visible via subsequent "log read" commands.  If we
can do that with a different session name and/or output path,
that would probably be sufficient.

>> But this is very slow in some cases.  The lttng load in particular is
>> extremely slow when Linux is running inside a virtual machine.
>
> I will test that. Not sure what would cause the load command to be slow
> inside a vm particularly.
> The " lttng stop" and "rm -rf" are most probably taking more time than
> the load command.

It's definitely the load command that is the killer in our
environment.  I'd send you output from the time command, except that
time inside our VM is pretty much meaningless because it's an event
driven simulation where time runs fast when there is little to do
and slow when there is lots to do.  This is an ARM instruction set
simulator that does run fairly slowly on our x86_64 machines, but the
"log clear" command stands out as running considerably more slowly
than other commands, especially given that conceptually at least,
it's not doing very much.  Overall, our existing implementation of
"log clear" takes about 25 seconds, and 20 seconds of that (give
or take) is from the lttng load command.

> Could you give us more information regarding the configuration you are
> loading? Number of channels, enabled events, type of session (live, to
> disk, streaming).

I hope the answers are all contained within the xcs_trace.lttng file included below.

> So far I do not see any dumb questions. :P

That's a relief :-)

Here's the contents of xcs_trace.lttng, the file saved by the "lttng save"
command:

======== begin xcs_trace.lttng ========
<?xml version="1.0" encoding="UTF-8"?>
<sessions>
    <session>
        <name>xcs_trace</name>
        <shared_memory_path>/var/log/lttng/shm/current/xcs_trace-20000101-000000</shared_memory_path>
        <domains>
            <domain>
                <type>UST</type>
                <buffer_type>PER_UID</buffer_type>
                <channels>
                    <channel>
                        <name>ch1</name>
                        <enabled>true</enabled>
                        <overwrite_mode>OVERWRITE</overwrite_mode>
                        <subbuffer_size>131072</subbuffer_size>
                        <subbuffer_count>16</subbuffer_count>
                        <switch_timer_interval>0</switch_timer_interval>
                        <read_timer_interval>0</read_timer_interval>
                        <output_type>MMAP</output_type>
                        <tracefile_size>0</tracefile_size>
                        <tracefile_count>0</tracefile_count>
                        <live_timer_interval>0</live_timer_interval>
                        <events>
                            <event>
                                <name>*</name>
                                <enabled>true</enabled>
                                <type>TRACEPOINT</type>
                                <loglevel_type>RANGE</loglevel_type>
                                <loglevel>6</loglevel>
                            </event>
                            <event>
                                <name>com_ericsson_tri*</name>
                                <enabled>true</enabled>
                                <type>TRACEPOINT</type>
                                <loglevel_type>RANGE</loglevel_type>
                                <loglevel>14</loglevel>
                            </event>
                        </events>
                        <contexts/>
                    </channel>
                </channels>
                <trackers/>
            </domain>
            <domain>
                <type>JUL</type>
                <buffer_type>PER_UID</buffer_type>
                <channels/>
            </domain>
            <domain>
                <type>LOG4J</type>
                <buffer_type>PER_UID</buffer_type>
                <channels/>
            </domain>
            <domain>
                <type>PYTHON</type>
                <buffer_type>PER_UID</buffer_type>
                <channels/>
            </domain>
        </domains>
        <started>true</started>
        <attributes>
            <snapshot_mode>true</snapshot_mode>
        </attributes>
        <output>
            <snapshot_outputs>
                <output>
                    <name>snapshot-1</name>
                    <max_size>0</max_size>
                    <consumer_output>
                        <enabled>true</enabled>
                        <destination>
                            <path>/pramfs/log/lttng/snapshot</path>
                        </destination>
                    </consumer_output>
                </output>
            </snapshot_outputs>
        </output>
    </session>
</sessions>
========== end xcs_trace.lttng ==============

Regards,
Doug


_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Fast way to clear trace logs and continue tracing?

[Douglas Graham]

Hi,

I just started working with lttng recently, so apologies if this is a dumb question.

Suppose I have configured and started a session and have collected a bunch of traces in a trace file.  Now I want to clear those traces but then continue saving new traces using the same session.  Is there a reasonably fast way to do that?

What we currently do is "lttng save --output-path=x.cfg; lttng stop; lttng destroy; rm -rf <tracedir>; lttng load --input-path=x.cfg

But this is very slow in some cases.  The lttng load in particular is extremely slow when Linux is running inside a virtual machine.  I was hoping that lttng might support a "lttng clear" that could be used to remove all traces from the trace file, but I can't find any such command.

I note that lttng does support the rotating of trace files when they reach a size limit.  I think that's fairly close to what I want.  If I could force a trace file rotation at an arbitrary time and then simple remove the old rotated log, leaving the new one, that seems like it should do the job.  Except I don't see any way to force a rotation.

Any ideas?

Thanks,
Doug
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev