What happened in the process LoRa message delivery? Can I measure or get the precise time cost of it?

[RyverSolare]

Hi, everyone.
I am applying a clock synchronization algorithm on LoPy4 modules. And I am trying to get rid of the time cost on message delivery of LoRa.
Are there any documents of reference describing the process of LoRa message delivery on LoPy4? For example, how long time it takes to encode and send out a message? How long it takes to receive and decode the message?
I have found that there is a tx_time_on_air attribute in
lora.stats(), however, this attribute is in the unit of milliseconds, can I get a more precise value in microseconds? Moreover, I have no idea what this time stands for. I have done some experiment on it:

def recvMsg(my_lora):
    call_back = localClk.read_us()
    recv_msg = socket.recv(16)
    stats = my_lora.stats()
    if(recv_msg == b's@1234'):
        record_time = localClk.read_us()
        localClk.reset()
        socket.send('m@1234')
        print('send cost', localClk.read_us())
        print('on_callback', record_time)
        print('on the air', stats[7] * 1000)
        print('uncertain', record_time / 2 - stats[7] * 1000 - (record_time - call_back))

time.sleep(5)
localClk = Timer.Chrono()
localClk.start()
result = []
result_time = []
# Set up LoRa
lora = LoRa(mode=LoRa.LORA, region=LoRa.EU868)
socket = socket.socket(socket.AF_LORA, socket.SOCK_RAW)
lora.callback(trigger=LoRa.RX_PACKET_EVENT, handler=recvMsg)
time.sleep(10)

One master node executes the code above, and another slave node just responses to the message it receives. The result is like:

send cost 42302.07
on_callback 88978.02
on the air 37000
uncertain 7292.387

Seems that socket.send() takes 42ms to execute. But the send time + transport on the air + receive time is about 44ms (half of duration of two on_callback), and the tx_time_on_air attribute is 37ms. What went wrong here?
If you have any ideas or clues about the LoRa message delivery process here, please do let me know. Thank you very much in advance.

[RyverSolare]

@robert-hh Thank you many times. It helps a lot.

[robert-hh]

@RyverSolare The source code is here: https://github.com/pycom/pycom-micropython-sigfox. The readme's at various levels contain instructions how to build it. Please follow them literally. The source code is not easy to understand, simply because it is large. An the Lora components are distributed over many files in a few folders.
For you purpose you may work with average values. But still the error of a single event will be in the ms range.

A small correction: it's not pipes but queues which are used for inter-task communication.

[RyverSolare]

@robert-hh Thank you very much for responding. I am a layman of embedded software and RTOS. I understand that since the task is scheduled by OS, the specific time of executing it (e.g. sending a message) is not possible to get, right? The process is impacted by the current workload of the system. Do you consider it makes sense to measure the average time cost given a fixed program (i.e. a fixed workload) and use this data?
By the way, would you please tell me where to find the source code related to the LoPy libraries? I have searched it on Github but I got nothing.
Thank you again, you are really warmhearted.

[robert-hh]

@RyverSolare That's what I understood form reading the source code once: The front-end of LoRa with the python API and the actual send/receive function run in two different RTOS tasks, which communicate via pipes. So timing depends on the RTOS scheduler. When packets are received, an ISR is called, which sets up the data for the further processing in the receive tasks, which then signals to the micropython task. Other tasks may interfere too, like WiFi activity. I did not find information about the basic scheduler tick of RTOS, but the order of 1 ms sounds like a reasonable assumption.