Osmocom Libraries » libosmocore

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