Project

General

Profile

Actions

Bug #5818

open

multithreaded logging causes lock contention and needs a rework

Added by Hoernchen about 1 year ago. Updated about 2 months ago.

Status:
New
Priority:
Normal
Assignee:
-
Category:
libosmocore
Target version:
-
Start date:
12/07/2022
Due date:
% Done:

0%

Spec Reference:

Description

The problem is that even just checking the log level requires locking and unlocking, which means that eeven if logging is not even active there is significant lock contention for doing nothing. This should be reworked by transforming the log levels to bitflags or some other lock free data structure that can be queried without locking anything unless logging actually happens.

Random quick trace of osmotrx that shows the time to acquire the lock:


@lock_latency_ns[0x7f556d144fb0, 
    log_tgt_mutex_lock_impl+29
    log_check_level+42
    Log::~Log()+684
    Transceiver::writeClockInterface()+192
    Transceiver::driveReceiveRadio()+412
, RxLower]: 
[1K, 2K)               1 |@@@@@@@@@@@@@@@@@@@@@@@@@@                          |
[2K, 4K)               1 |@@@@@@@@@@@@@@@@@@@@@@@@@@                          |
[4K, 8K)               0 |                                                    |
[8K, 16K)              2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[16K, 32K)             2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|

@lock_latency_ns[0x7f556d144fb0, 
    log_tgt_mutex_lock_impl+29
    osmo_vlogp+49
    logp2+153
    Log::~Log()+880
    Transceiver::writeClockInterface()+192
, RxLower]: 
[1K, 2K)               3 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[2K, 4K)               3 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|

@lock_latency_ns[0x7f556d144fb0, 
    log_tgt_mutex_lock_impl+29
    osmo_vlogp+49
    logp2+153
    Log::~Log()+880
    Transceiver::logRxBurst(unsigned long, trx_ul_burst_ind const*)+1999
, RxUpper0]: 
[1K, 2K)               8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[2K, 4K)               6 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@             |

@lock_latency_ns[0x7f556d144fb0, 
    log_tgt_mutex_lock_impl+29
    log_check_level+42
    Transceiver::driveReceiveFIFO(unsigned long)+430
    RxUpperLoopAdapter(TrxChanThParams*)+169
    start_thread+755
, RxUpper0]: 
[1K, 2K)               2 |@@@@@@@@@@@@@@                                      |
[2K, 4K)               7 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4K, 8K)               3 |@@@@@@@@@@@@@@@@@@@@@@                              |
[8K, 16K)              2 |@@@@@@@@@@@@@@                                      |

@lock_latency_ns[0x7f556d144fb0, 
    log_tgt_mutex_lock_impl+29
    log_check_level+42
    Log::~Log()+684
    Transceiver::logRxBurst(unsigned long, trx_ul_burst_ind const*)+1999
    Transceiver::driveReceiveFIFO(unsigned long)+462
, RxUpper0]: 
[1K, 2K)               4 |@@@@@@@@@@@@@@@@@@@@                                |
[2K, 4K)              10 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|

@lock_latency_ns[0x5652e97c7030, 
    reap_for_handle+505
    0x5652e9750598
, osmo-trx-uhd]: 
[1K, 2K)              12 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[2K, 4K)               5 |@@@@@@@@@@@@@@@@@@@@@                               |
[4K, 8K)               0 |                                                    |
[8K, 16K)              1 |@@@@                                                |
[16K, 32K)             1 |@@@@                                                |

Actions #1

Updated by Hoernchen about 2 months ago

  • Status changed from New to Resolved
  • % Done changed from 0 to 100
Actions #2

Updated by fixeria about 2 months ago

  • Status changed from Resolved to New
  • % Done changed from 100 to 0
Actions

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)