Project

General

Profile

Feature #5032

Add VTY option to write TID in log line prefix

Added by pespin 12 days ago. Updated 11 days ago.

Status:
Feedback
Priority:
Normal
Assignee:
Category:
-
Target version:
-
Start date:
02/17/2021
Due date:
% Done:

80%

Spec Reference:

Description

Similar to other options to prefix log lines with several information, it would be nice having some generic integrated way to log TID on each line, to ease debug and udnerstanding of multi-threaded processes.

A command under "logging ..." node, something like: "logging print tid (0|1)", which would be disabled by default.

This can easily be implemented now that we have "osmo_gettid()" API (see #5027).

We could even have an internal __thread variable with some osmo_gettid_cached() internal API which would fill the __thread variable if it is == 0, in order to avoid calling gettid() and potentially issuing a syscall everytime.

See as an example:
https://gerrit.osmocom.org/c/libosmocore/+/22952 logging: gsmtap: Store TID instead of PID in pkt hdr


Related issues

Related to libosmocore - Bug #5027: logging_gsmtap.c code not filling PID field in pkt headerResolved02/16/2021

Associated revisions

Revision 662d10dc (diff)
Added by pespin 10 days ago

logging: Allow prefixing thread ID to each log line

Related: OS#5032
Change-Id: I38fc93ab0182b4edbd639c7ed0f31ce51964ee18

History

#1 Updated by pespin 11 days ago

  • Related to Bug #5027: logging_gsmtap.c code not filling PID field in pkt header added

#2 Updated by pespin 11 days ago

Submitted here:
https://gerrit.osmocom.org/c/libosmocore/+/22960 logging: Allow prefixing thread ID to each log line

I tested it with osmo-trx-uhd and it looks good (see second column):

20210218183349610 445807 DLGLOBAL <0008> cpu_sched_vty.c:470 Setting SCHED_RR priority 18
20210218183349610 445807 DLGLOBAL <0008> telnet_interface.c:104 Available via telnet 127.0.0.1 4237
20210218183349610 445807 DLCTRL <000f> control_if.c:916 CTRL at 127.0.0.1 4236
20210218183349610 445807 DMAIN <0000> osmo-trx.cpp:495 SSE3 support compiled in and supported by CPU
20210218183349610 445807 DMAIN <0000> osmo-trx.cpp:507 SSE4.1 support compiled in and supported by CPU
20210218183349610 445807 DMAIN <0000> osmo-trx.cpp:561 [tid=140304886954240] Config Settings
   Log Level............... 0
   Device args............. type=b200
   TRX Base Port........... 5700
   TRX Address............. 192.168.30.100
   GSM BTS Address......... 192.168.30.1
   Channels................ 1
   Tx Samples-per-Symbol... 4
   Rx Samples-per-Symbol... 4
   EDGE support............ 1
   Extended RACH support... 0
   Reference............... 0
   Filler Burst Type....... Empty bursts
   Filler Burst TSC........ 0
   Filler Burst RACH Delay. 0
   Multi-Carrier........... 1
   Tuning offset........... 0
   RSSI to dBm offset...... 0 (relative)
   Swap channels........... 0
   Tx Antennas............. '<default>'
   Rx Antennas............. '<default>'

20210218183349610 445807 DLGLOBAL <0008> rate_ctr.c:87 validating counter group 0x555fc07a90a0(trx:chan) with 14 counters
20210218183349611 445807 DDEV <0005> UHDDevice.cpp:175 [tid=140304886954240] Multi-ARFCN: 1 logical chans -> 1 physical chans
[INFO] [UHD] linux; GNU C++ version 10.2.0; Boost_107500; UHD_4.0.0.0-0-unknown
20210218183349644 445808 DDEVDRV <0006> b200_iface.cpp:219 [tid=140304830166592] [B200] Loading firmware image: /usr/share/uhd/images/usrp_b200_fw.hex...
20210218183351696 445807 DDEV <0005> UHDDevice.cpp:571 [tid=140304886954240] Using discovered UHD device type=b200,name=MyB200,serial=3166C0B,product=B200
20210218183351895 445808 DDEVDRV <0006> b200_impl.cpp:420 [tid=140304830166592] [B200] Detected Device: B200
20210218183351960 445808 DDEVDRV <0006> b200_iface.cpp:565 [tid=140304830166592] [B200] Loading FPGA image: /usr/share/uhd/images/usrp_b200_fpga.bin...
20210218183401463 445808 DDEVDRV <0006> b200_impl.cpp:467 [tid=140304830166592] [B200] Operating over USB 3.
20210218183401476 445808 DDEVDRV <0006> b200_impl.cpp:522 [tid=140304830166592] [B200] Detecting internal GPSDO....
20210218183402277 445808 DDEVDRV <0006> gps_ctrl.cpp:243 [tid=140304830166592] [GPS] No GPSDO found
20210218183402289 445808 DDEVDRV <0006> b200_impl.cpp:618 [tid=140304830166592] [B200] Initialize CODEC control...
20210218183402591 445808 DDEVDRV <0006> b200_impl.cpp:687 [tid=140304830166592] [B200] Initialize Radio control...
20210218183402632 445808 DDEVDRV <0006> b200_impl.cpp:1100 [tid=140304830166592] [B200] Performing register loopback test...
20210218183402652 445808 DDEVDRV <0006> b200_impl.cpp:1109 [tid=140304830166592] [B200] Register loopback test passed
20210218183402685 445808 DDEVDRV <0006> b200_impl.cpp:815 [tid=140304830166592] [B200] Setting master clock rate selection to 'automatic'.
20210218183402685 445808 DDEVDRV <0006> b200_impl.cpp:1150 [tid=140304830166592] [B200] Asking for clock rate 16.000000 MHz...
20210218183403011 445808 DDEVDRV <0006> b200_impl.cpp:1163 [tid=140304830166592] [B200] Actually got clock rate 16.000000 MHz.
20210218183403172 445807 DMAIN <0000> UHDDevice.cpp:222 [tid=140304886954240] Antennas configured successfully
20210218183403180 445808 DDEVDRV <0006> multi_usrp.cpp:504 [tid=140304830166592] [MULTI_USRP] Setting master clock rate selection to 'manual'.
20210218183403180 445808 DDEVDRV <0006> b200_impl.cpp:1150 [tid=140304830166592] [B200] Asking for clock rate 51.200000 MHz...
20210218183403392 445808 DDEVDRV <0006> b200_impl.cpp:1163 [tid=140304830166592] [B200] Actually got clock rate 51.200000 MHz.
20210218183403494 445807 DDEV <0005> UHDDevice.cpp:345 [tid=140304886954240] Rates configured for B200/B210 4 SPS Multi-ARFCN
20210218183403543 445807 DDEV <0005> UHDDevice.cpp:305 [tid=140304886954240] Supported Tx gain range [0; 89.75]
20210218183403543 445807 DDEV <0005> UHDDevice.cpp:310 [tid=140304886954240] Supported Rx gain range [0; 76]
20210218183403543 445807 DDEV <0005> UHDDevice.cpp:314 [tid=140304886954240] Default setting Tx gain for channel 0 to 44.875
20210218183403543 445807 DDEV <0005> UHDDevice.cpp:321 [tid=140304886954240] Default setting Rx gain for channel 0 to 38
20210218183403544 445807 DDEV <0005> UHDDevice.cpp:670 [tid=140304886954240] Device configuration: Single USRP:
  Device: B-Series Device
  Mboard 0: B200
  RX Channel: 0
    RX DSP: 0
    RX Dboard: A
    RX Subdev: FE-RX1
  TX Channel: 0
    TX DSP: 0
    TX Dboard: A
    TX Subdev: FE-TX1
20210218183403561 445807 DMAIN <0000> osmo-trx.cpp:609 [tid=140304886954240] -- Transceiver active with 1 channel(s)
20210218183403561 445807 DLSTATS <0011> stats.c:160 Stats timer expire_count=3: We missed 2 timers

#3 Updated by pespin 11 days ago

  • Status changed from New to Feedback
  • Assignee set to pespin
  • % Done changed from 0 to 80

The tid=... stuff from osmo-trx is actually printing the pthread related struct, which shouldn't be printed as an integer because specs don't even guarantee that's an integer. Specs says it's an opaque structure.

So, once the libosmocore patch is merged, I will remove those tid=... printings from osmo-trx.

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)