Problem with vpid in lttng output

Problem with vpid in lttng output

[Aleksander Twardowski via lttng-dev]

[-- Attachment #1.1: Type: text/plain, Size: 881 bytes --]

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" }

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" }”

If you can help me, tell me in which cases this problem occurring that would be great.
I checked https://github.com/lttng/lttng-ust but I did not found any clue.

BR,
Aleksander

[-- Attachment #1.2: Type: text/html, Size: 3617 bytes --]

[-- Attachment #2: Type: text/plain, Size: 156 bytes --]

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

Re: Problem with vpid in lttng output

[Jonathan Rajotte-Julien]

Hi,

Note that the restriction to prevent an add-context command on a
started session is not present in 2.10.2. It is present starting at 2.10.3.

 joraj@~/lttng/stable-2.10/lttng-tools [(v2.10.7)][]$ git tag --contains 3aaf55eaa5aee2db6e2a1a46685e45f2395fc15b
 v2.10.3
 v2.10.4
 v2.10.5
 v2.10.6
 v2.10.7

This would explain why you can issue the commands in the order you are issuing
them currently (add-context after start).

 lttng create csim_session_rpup -o /tmp/csim_session_rpup
 lttng enable-event -u
 lttng start csim_session_rpup
 lttng add-context -u -t vpid
 lttng track -u -s csim_session_rpup --all

To comply with this without upgrading, you can swap the order of the add-context
and start command.

commands:

 lttng create
 lttng enable-event -u ...
 lttng add-context -u -t vpid
 lttng start
 lttng track ...

I did some experiment using v2.10.2 to reproduce the issue.
I used the same sequence of commands you provided:

 lttng create csim_session_rpup -o /tmp/csim_session_rpup
 lttng enable-event -u
 lttng start csim_session_rpup
 lttng add-context -u -t vpid
 lttng track -u -s csim_session_rpup --all

At first, I tried a scenario where the only instrumented (registered) app is run
after the add-context. No other instrumented apps were running at the moment the
"lttng start" was issued. The trace produced contained the vpid context.

What happen if an instrumented app is already running when the "lttng start"
command is issued? The "lttng add-context" does not report any problem yet the
resulting trace does not contain any vpid context.

In the lttng-sessiond logs we see that the add-context command failed for the app:

  DEBUG2 - 11:19:43.718781 [9499/9506]: UST app adding context to channel channel0 (in create_ust_app_channel_context() at ust-app.c:2357)
  DEBUG3 - 11:19:43.718784 [9499/9506]: UST app context 1 allocated (in alloc_ust_app_ctx() at ust-app.c:1146)
  Error: UST app create channel context failed for app (pid: 7350) with ret -1028
  Error: Failed to add context to channel channel0

The first scenario works because we delay the setup of the channel until an app
eligible for tracing is present.

That should be it.

Cheers

-- 
Jonathan Rajotte-Julien
EfficiOS

Re: Problem with vpid in lttng output

[Aleksander Twardowski via lttng-dev]

Hi,

Thanks for your answer!
Please find my answers.

BR,
Aleksander

-----Original Message-----
From: Jonathan Rajotte-Julien <jonathan.rajotte-julien@efficios.com> 
Sent: poniedziałek, 2 września 2019 21:34
To: Aleksander Twardowski <aleksander.twardowski@ericsson.com>
Cc: lttng-dev@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
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: Problem with vpid in lttng output

[Jonathan Rajotte-Julien]

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?

> 
> 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.

Cheers

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

Re: Problem with vpid in lttng output

[Aleksander Twardowski via lttng-dev]

[-- Attachment #1.1: Type: text/plain, Size: 1119 bytes --]

Adding ltng version:
lttng --version
lttng (LTTng Trace Control) 2.10.2 - KeKriek

From: Aleksander Twardowski
Sent: poniedziałek, 2 września 2019 14:02
To: lttng-dev@lists.lttng.org
Subject: Problem with vpid in lttng output

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" }

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" }”

If you can help me, tell me in which cases this problem occurring that would be great.
I checked https://github.com/lttng/lttng-ust but I did not found any clue.

BR,
Aleksander

[-- Attachment #1.2: Type: text/html, Size: 5030 bytes --]

[-- Attachment #2: Type: text/plain, Size: 156 bytes --]

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