Thread with highest priority(255) running too much time on QNX 7.1

273 Views Asked by At

We have a thread (named Patie#ty_2TimTh in the below attachment) with priority 255 running on QNX 7.1. The host is X86 with 12 CPU Core. This thread affinity is set to CPU 7/8/9, and the maximum CPU partition is 20% (less than 3/12=25%). This thread loops forever to receive pulse event and post semaphore to notify work thread. The looping pseudo code lists below:

while (true) {
    MsgReceivePulse();
    ret = sem_getvalue(sem, value);
    if (!((0 == ret) && (value > 0))) {
        sem_post(sem); // post only value <= 0
    }
}

The running time of the above code is about 10us. But we found the running time was nearly 3ms sometimes, when we used QNX tracelogger to catch some events. See the attachment.

enter image description here

This thread's events list below:

Event,  Time,        Cycle,       CPU, Owner,                Class,       Type,   Data
696441, 613ms 438us, 0x265209E82, 7, safety Patie#ty_2TimTh, Process and Thread, Running, policy_name FIFO pid 9424945 tid 34 priority 255 policy 1 partition 7 sched_flags 0
696442, 613ms 438us, 0x26520A3C0, 7, safety Patie#ty_2TimTh, Communication, Receive Pulse, scoid 0x10005 pid 9424945 process safety
696443, 613ms 438us, 0x26520A4FA, 7, safety Patie#ty_2TimTh, Kernel Calls, MsgReceivePulsev (64) Exit, rcvid 0x0 rmsg0 0x0 rmsg1 0x0 rmsg2 0x0 info->nd 0 info->srcnd 0 info->pid 0 info->tid 0 info->chid 0 info->scoid 0 info->msglen 0 info->srcmsglen 0 info->dstmsglen 0 info->priority 0 info->flags 0 info->reserved 0
696885, 613ms 762us, 0x265306EF0, 7, safety Patie#ty_2TimTh, System, IPI (64), ipicmd 0x20 CHECK_INTR ipi 0x257f781317 tid 34 pid 9424945 process safety
696903, 613ms 777us, 0x2653128D0, 7, safety Patie#ty_2TimTh, Process and Thread, Running, policy_name FIFO pid 9424945 tid 34 priority 255 policy 1 partition 7 sched_flags 0
698114, 614ms 762us, 0x265612411, 7, safety Patie#ty_2TimTh, System, IPI (64), ipicmd 0x20 CHECK_INTR ipi 0x257f781317 tid 34 pid 9424945 process safety
698134, 614ms 781us, 0x265620D94, 7, safety Patie#ty_2TimTh, Process and Thread, Running, policy_name FIFO pid 9424945 tid 34 priority 255 policy 1 partition 7 sched_flags 0
698691, 615ms 181us, 0x26575868B, 7, safety Patie#ty_2TimTh, Kernel Calls, SyncSemPost (64) Enter, sync_ptr 0x1e3b814a7c count 0 owner 0xfffffffc
698693, 615ms 183us, 0x26575A3DE, 7, safety Patie#ty_2TimTh, Kernel Calls, SyncSemPost Exit, ret_val 0x0
699423, 615ms 763us, 0x26591DC0B, 7, safety Patie#ty_2TimTh, System, IPI (64), ipicmd 0x20 CHECK_INTR ipi 0x257f7810ed tid 34 pid 9424945 process safety
699451, 615ms 786us, 0x26592FE48, 7, safety Patie#ty_2TimTh, Process and Thread, Running, policy_name FIFO pid 9424945 tid 34 priority 255 policy 1 partition 7 sched_flags 0
699846, 616ms 99us, 0x265A23AE1, 7, safety Patie#ty_2TimTh, Kernel Calls, MsgReceivePulsev (64) Enter, chid 0x9 rparts 1

From the attachment, we found this thread is always running(yellow bar) and there are many Control events, such as.

696454, 613ms 446us, 0x265210A7F, 1, , Control Events, Buffer, sequence_number 6216609 event_count 0
696455, 613ms 447us, 0x2652112FE, 1, , Control Events, Time, msb 0x174d lsb 0x652112fe
696459, 613ms 451us, 0x265214063, 9, , Control Events, Time, msb 0x174d lsb 0x65214063

So why is this thread with highest priority running so long? Is it because tracelogger is running or aps partition has exceed 20% and kernel limits this thread's running time? Thanks very much.

0

There are 0 best solutions below