[lttng-dev] Problem with vpid in lttng output

[Aleksander Twardowski]

Hi,

Thanks for your answer!
Please find my answers.

BR,
Aleksander

-----Original Message-----
From: Jonathan Rajotte-Julien <jonathan.rajotte-julien at efficios.com> 
Sent: poniedziałek, 2 września 2019 21:34
To: Aleksander Twardowski <aleksander.twardowski at ericsson.com>
Cc: lttng-dev at lists.lttng.org
Subject: Re: [lttng-dev] Problem with vpid in lttng output

Hi Aleksander,

On Mon, Sep 02, 2019 at 12:01:46PM +0000, Aleksander Twardowski via lttng-dev wrote:
> Hi,
> 
> I do not know if I am addressing problem correctly but let’s try 😊
> I have a problem, occurring very rarely, with vpid in lttng output.
> Sometimes, I do not know why, vpid is not visible.
> 
> Proper lttng log:
> [14:08:35.156333670] (+0.000010724) selilsx1795 
> com_ericsson_csim_up:ERROR: { cpu_id = 0 }, { vpid = 16826 }, { src = 
> "/home/ealetwa/repos/bpu-up/src/Rpup.cpp:125:", obj = "GENERAL", msg = 
> "Failed to initialize SDS connection" }

Side note: make sure to redact information that could be sensitive. Here the payload and event name could be considered sensitive. It is up to you to evaluate what is sensitive and what is not.

> 
> Problematic lttng log:
> “[14:08:35.156333670] (+0.000010724) selilsx1795 com_ericsson_csim_up:ERROR: { cpu_id = 0 }, { src = "/home/ealetwa/repos/bpu-up/src/Rpup.cpp:125:", obj = "GENERAL", msg = "Failed to initialize SDS connection" }”

Does this situation happen inside the same trace? Or does it seems to happens between traces?
[Aleksander] Nope, situation occurs for different traces and even different sessions. No connection between. We are running our application and running lttng traces for every test case which we are running.

> 
> If you can help me, tell me in which cases this problem occurring that would be great.

We are not aware of any ongoing issue with the context subsystem. A first step would be to validate that the "lttng add-context" (or equivalent) was performed without any error for the session of the trace with the vpid information missing. Note that you cannot add context field for a tracing session if it was started at least once.
[Aleksander] : Maybe I will share steps for setting up session.

lttng create csim_session_rpup -o /tmp/csim_session_rpup
	Session csim_session_rpup created.
	Traces will be written in /tmp/csim_session_rpup
lttng enable-event -u com_ericsson_csim_dpdk_up:ERROR,com_ericsson_csim_dpdk_up:WARNING,com_ericsson_csim_cli_up:ERROR,com_ericsson_csim_cli_up:WARNING,com_ericsson_csim_up:ERROR,com_ericsson_csim_up:WARNING,com_ericsson_csim_packet_up:ERROR,com_ericsson_csim_packet_up:WARNING,com_ericsson_csim_grpc_server_up:ERROR,com_ericsson_csim_grpc_server_up:WARNING,
	UST event com_ericsson_csim_dpdk_up:ERROR created in channel channel0
 	UST event com_ericsson_csim_dpdk_up:WARNING created in channel channel0
	 UST event com_ericsson_csim_cli_up:ERROR created in channel channel0
	 UST event com_ericsson_csim_cli_up:WARNING created in channel channel0
	 UST event com_ericsson_csim_up:ERROR created in channel channel0
	 UST event com_ericsson_csim_up:WARNING created in channel channel0
	 UST event com_ericsson_csim_packet_up:ERROR created in channel channel0
	 UST event com_ericsson_csim_packet_up:WARNING created in channel channel0
	 UST event com_ericsson_csim_grpc_server_up:ERROR created in channel channel0
	 UST event com_ericsson_csim_grpc_server_up:WARNING created in channel channel0

lttng start csim_session_rpup
	Tracing started for session csim_session_rpup
lttng add-context -u -t vpid
	UST context vpid added to all channels
lttng track -u -s csim_session_rpup --all
	All PIDs tracked in session csim_session_rpup

Then we are starting our application.

At the end of TC we are checking lttng logs:

lttng list csim_session_rpup
	Tracing session csim_session_rpup: [active]
     Trace path: /tmp/csim_session_rpup
 
 === Domain: UST global ===
 
 Buffer type: per UID
 
 Channels:
 -------------
 - channel0: [enabled]
 
     Attributes:
       Event-loss mode:  discard
       Sub-buffer size:  524288 bytes
       Sub-buffer count: 4
       Switch timer:     inactive
       Read timer:       inactive
       Monitor timer:    1000000 µs
       Blocking timeout: 0 µs
       Trace file count: 1 per stream
       Trace file size:  unlimited
       Output mode:      mmap
 
     Statistics:
       Discarded events: 0
 
     Event rules:
       com_ericsson_csim_grpc_server_up:WARNING (type: tracepoint) [enabled]
       com_ericsson_csim_dpdk_up:WARNING (type: tracepoint) [enabled]
       com_ericsson_csim_packet_up:ERROR (type: tracepoint) [enabled]
       com_ericsson_csim_grpc_server_up:ERROR (type: tracepoint) [enabled]
       com_ericsson_csim_dpdk_up:ERROR (type: tracepoint) [enabled]
       com_ericsson_csim_up:ERROR (type: tracepoint) [enabled]
       com_ericsson_csim_cli_up:WARNING (type: tracepoint) [enabled]
       com_ericsson_csim_packet_up:WARNING (type: tracepoint) [enabled]
       com_ericsson_csim_cli_up:ERROR (type: tracepoint) [enabled]
       com_ericsson_csim_up:WARNING (type: tracepoint) [enabled]

lttng stop csim_session_rpup
	Waiting for data availability.
	 Tracing stopped for session csim_session_rpup
babeltrace /tmp/csim_session_rpup -w /tmp/lttng_csim_session_rpup.log
rm -rf /tmp/csim_session_rpup
lttng destroy csim_session_rpup

And then we have a check lttng log if expected log are in place. There, inside the log we have this problematic log (without vpid):
[13:52:00.891966858] (+0.000007753) seliics02747 com_ericsson_csim_up:ERROR: { cpu_id = 0 }, { src = "/local/jenkins/workspace/T-SBC_rpup/bpu-up/src/Rpup.cpp:124:", obj = "GENERAL", msg = "Failed to initialize SDS connection" }
	
Problem occurs very rarely, last sentence from your mail maybe be the clue ". Note that you cannot add context field for a tracing session if it was started at least once".
Maybe if session is not closed properly, then we can see such problems?

Cheers

--
Jonathan Rajotte-Julien
EfficiOS