The paper An Empirical Study on the Adequacy of MBPTA for Tasks Executed on a Complex Computer Architecture with Linux, which I am co-author, was awared with traveling funding by  the IEEE IES S&YP!

Karila and Luis Fernando made a video about the paper, check this out:

Systemd supports the setup of real-time priority to services launched during the boot process. This is done using the following Directives in the Service section:

• CPUSchedulingPolicy=
  Sets the CPU scheduling policy for executed processes. Takes one of other, batch, idle, fifo or rr.
• CPUSchedulingPriority=
  Sets the CPU scheduling priority for executed processes. The available priority range depends on the selected CPU scheduling policy. For real-time scheduling policies, an integer between 1 (lowest priority) and 99 (highest priority) can be used.

Example

This is the mcelog service unity:

[Unit]
Description=Machine Check Exception Logging Daemon

[Service]
ExecStart=/usr/sbin/mcelog --ignorenodev --daemon --foreground

[Install]
WantedBy=multi-user.target

By adding the following directives in Service section:

CPUSchedulingPolicy=fifo
CPUSchedulingPriority=20

For example:

[Unit]
Description=Machine Check Exception Logging Daemon

[Service]
ExecStart=/usr/sbin/mcelog --ignorenodev --daemon --foreground
CPUSchedulingPolicy=fifo
CPUSchedulingPriority=20

[Install]
WantedBy=multi-user.target

When restarted, the mcelog service will start with the priority set by systemd:

# tuna --show_threads | grep mcelog
4680 FIFO 20 0,1 2 0 mcelog

Here is one example of the trace of the problem I reported in this e-mail to the LKML

Note Patch accepted! This patch is the first change that was proposed by the analysis of the task model I am developing in my Ph.D. Thesis.

Trace setup

The trace setup I am using is the following:

# cd /sys/kernel/debug/tracing/
# echo preempt_schedule_irq schedule schedule_preempt_disabled schedule_idle schedule_user >> set_graph_function ; done 
# echo function_graph > current_tracer
# echo sched:sched_switch sched:sched_wakeup > set_event
# echo irq_vectors >> set_event
# echo $(( 1408 * 100 )) > buffer_size_kb
# echo > trace

In addition, I added a trace_prink() at the entry and exit of __schedule() and another when there is no context switch (because __schedule() is notrace).

diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 70641e8f3c89..406a0b7ed6b3 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -3443,6 +3443,7 @@ static void __sched notrace __schedule(bool preempt)
        struct rq *rq;
        int cpu;
 
+       trace_printk("__schedule_entry\n");
        cpu = smp_processor_id();
        rq = cpu_rq(cpu);
        prev = rq->curr;
@@ -3517,9 +3518,11 @@ static void __sched notrace __schedule(bool preempt)
        } else {
                rq->clock_update_flags &= ~(RQCF_ACT_SKIP|RQCF_REQ_SKIP);
                rq_unlock_irq(rq, &rf);
+               trace_printk("oh boy, no context switch\n");
        }
 
        balance_callback(rq);
+       trace_printk("__schedule_exit\n");
 }

This is the perf cmd-line I am using to generate a load that turns the problem visible:

# perf record -o /dev/shm/lala

I ran perf for some seconds and then read the trace.

Trace analysis

The kworker-336 is running:

 ------------------------------------------
 0)   ktimers-8    =>  kworker-336  
 ------------------------------------------

  310.241851 |   0)  kworker-336   |               |    finish_task_switch() {
  310.241851 |   0)  kworker-336   |   0.183 us    |      preempt_count_sub();
  310.241853 |   0)  kworker-336   |   1.467 us    |    }
  310.241853 |   0)  kworker-336   |               |  /* __schedule_exit */
  310.241854 |   0)  kworker-336   |   0.229 us    |    preempt_count_sub();
  310.241855 |   0)  kworker-336   |               |    wq_worker_running() {
  310.241856 |   0)  kworker-336   |   0.280 us    |      kthread_data();
  310.241857 |   0)  kworker-336   |   1.569 us    |    }
  310.241858 |   0)  kworker-336   | * 39582.48 us |  }

At this point it calls the scheduler:

  310.242147 |   0)  kworker-336   |               |  schedule() {
  310.242148 |   0)  kworker-336   |               |    wq_worker_sleeping() {
  310.242149 |   0)  kworker-336   |   0.239 us    |      kthread_data();

while in the wakeup_worker() call:

  310.242151 |   0)  kworker-336   |               |      wake_up_worker() {
  310.242151 |   0)  kworker-336   |   0.186 us    |        preempt_count_add();
  310.242152 |   0)  kworker-336   |               |        wake_up_process() {
  310.242153 |   0)  kworker-336   |               |          try_to_wake_up() {

And another kworker is awakened:

  310.242153 |   0)  kworker-336   |   0.200 us    |            preempt_count_add();
  310.242155 |   0)  kworker-336   |   0.186 us    |            preempt_count_add();
  310.242156 |   0)  kworker-336   |               |            update_rq_clock() {
  310.242157 |   0)  kworker-336   |   0.193 us    |              kvm_steal_clock();
  310.242158 |   0)  kworker-336   |   1.610 us    |            }
  310.242159 |   0)  kworker-336   |               |            activate_task() {
  310.242160 |   0)  kworker-336   |               |              enqueue_task_fair() {
  310.242160 |   0)  kworker-336   |               |                enqueue_entity() {
  310.242161 |   0)  kworker-336   |               |                  update_curr() {
  310.242162 |   0)  kworker-336   |   0.249 us    |                    update_min_vruntime();
  310.242163 |   0)  kworker-336   |               |                    cpuacct_charge() {
  310.242164 |   0)  kworker-336   |   0.155 us    |                      __rcu_read_lock();
  310.242165 |   0)  kworker-336   |   0.160 us    |                      __rcu_read_unlock();
  310.242166 |   0)  kworker-336   |   2.495 us    |                    }
  310.242167 |   0)  kworker-336   |   0.161 us    |                    __rcu_read_lock();
  310.242168 |   0)  kworker-336   |   0.166 us    |                    __rcu_read_unlock();
  310.242169 |   0)  kworker-336   |   7.787 us    |                  }
  310.242170 |   0)  kworker-336   |   0.216 us    |                  update_cfs_group();
  310.242171 |   0)  kworker-336   |   0.216 us    |                  __enqueue_entity();
  310.242172 |   0)  kworker-336   | + 11.478 us   |                }
  310.242173 |   0)  kworker-336   |   0.158 us    |                hrtick_update();
  310.242174 |   0)  kworker-336   | + 13.759 us   |              }
  310.242174 |   0)  kworker-336   | + 15.052 us   |            }
  310.242175 |   0)  kworker-336   |               |            check_preempt_curr() {
  310.242176 |   0)  kworker-336   |               |              check_preempt_wakeup() {
  310.242176 |   0)  kworker-336   |   0.209 us    |                update_curr();
  310.242178 |   0)  kworker-336   |   0.158 us    |                wakeup_preempt_entity.isra.39();
  310.242179 |   0)  kworker-336   |   0.291 us    |                set_next_buddy();
  310.242180 |   0)  kworker-336   |   0.246 us    |                resched_curr_lazy();
  310.242182 |   0)  kworker-336   |   5.704 us    |              }
  310.242183 |   0)  kworker-336   |   7.150 us    |            }
  310.242184 |   0)  kworker-336   |               |            /* sched_wakeup: comm=kworker/0:2 pid=104 prio=120 target_cpu=000 */
  310.242184 |   0)  kworker-336   |   0.349 us    |            preempt_count_sub();
  310.242186 |   0)  kworker-336   |   0.214 us    |            preempt_count_sub();
  310.242187 |   0)  kworker-336   | + 34.075 us   |          }
  310.242188 |   0)  kworker-336   | + 35.213 us   |        }
  310.242189 |   0)  kworker-336   |               |        preempt_count_sub() {

And here __schedule is called:

  310.242190 |   0)  kworker-336   |               |          /* __schedule_entry */
  310.242190 |   0)  kworker-336   |               |          rcu_note_context_switch() {
  310.242191 |   0)  kworker-336   |   0.215 us    |            rcu_sched_qs();
  310.242192 |   0)  kworker-336   |   0.214 us    |            rcu_preempt_qs();
  310.242194 |   0)  kworker-336   |   2.982 us    |          }
  310.242194 |   0)  kworker-336   |   0.237 us    |          preempt_count_add();
  310.242196 |   0)  kworker-336   |               |          update_rq_clock() {
  310.242197 |   0)  kworker-336   |   0.209 us    |            kvm_steal_clock();
  310.242198 |   0)  kworker-336   |   1.657 us    |          }
  310.242199 |   0)  kworker-336   |               |          pick_next_task_fair() {
  310.242199 |   0)  kworker-336   |               |            update_curr() {
  310.242201 |   0)  kworker-336   |   0.261 us    |              update_min_vruntime();
  310.242202 |   0)  kworker-336   |               |              cpuacct_charge() {
  310.242203 |   0)  kworker-336   |   0.203 us    |                __rcu_read_lock();
  310.242204 |   0)  kworker-336   |   0.199 us    |                __rcu_read_unlock();
  310.242206 |   0)  kworker-336   |   2.838 us    |              }
  310.242206 |   0)  kworker-336   |   0.201 us    |              __rcu_read_lock();
  310.242207 |   0)  kworker-336   |   0.275 us    |              __rcu_read_unlock();
  310.242209 |   0)  kworker-336   |   8.898 us    |            }
  310.242209 |   0)  kworker-336   |   0.205 us    |            check_cfs_rq_runtime();
  310.242211 |   0)  kworker-336   |               |            pick_next_entity() {
  310.242212 |   0)  kworker-336   |   0.229 us    |              wakeup_preempt_entity.isra.39();
  310.242213 |   0)  kworker-336   |   0.317 us    |              clear_buddies();
  310.242214 |   0)  kworker-336   |   2.959 us    |            }
  310.242215 |   0)  kworker-336   |               |            put_prev_entity() {
  310.242216 |   0)  kworker-336   |   0.246 us    |              update_curr();
  310.242217 |   0)  kworker-336   |   0.214 us    |              check_cfs_rq_runtime();
  310.242218 |   0)  kworker-336   |   0.382 us    |              __enqueue_entity();
  310.242220 |   0)  kworker-336   |   4.481 us    |            }
  310.242220 |   0)  kworker-336   |   0.461 us    |            set_next_entity();
  310.242222 |   0)  kworker-336   | + 22.840 us   |          }

resulting in a context switch:

  310.242223 |   0)  kworker-336   |               |          /* sched_switch: prev_comm=kworker/0:7 prev_pid=336 prev_prio=120 prev_state=R+ ==> next_comm=kworker/0:2 next_pid=104 next_prio=120 */
  310.242224 |   0)  kworker-336   |   0.244 us    |          enter_lazy_tlb();
 ------------------------------------------
 0)  kworker-336   =>  kworker-104  
 ------------------------------------------
[ lines deleted ]

Until the point in which the kworker leaves the processor:

  310.243004 |   0)  kworker-104   |               |  /* __schedule_entry */
  310.243004 |   0)  kworker-104   |               |    rcu_note_context_switch() {
  310.243005 |   0)  kworker-104   |   0.171 us    |      rcu_sched_qs();
  310.243006 |   0)  kworker-104   |   0.167 us    |      rcu_preempt_qs();
  310.243007 |   0)  kworker-104   |   2.478 us    |    }
  310.243008 |   0)  kworker-104   |   0.184 us    |    preempt_count_add();
  310.243009 |   0)  kworker-104   |               |    update_rq_clock() {
  310.243009 |   0)  kworker-104   |   0.176 us    |      kvm_steal_clock();
  310.243011 |   0)  kworker-104   |   1.405 us    |    }
  310.243011 |   0)  kworker-104   |               |    deactivate_task() {
  310.243012 |   0)  kworker-104   |               |      dequeue_task_fair() {
  310.243012 |   0)  kworker-104   |               |        dequeue_entity() {
  310.243013 |   0)  kworker-104   |               |          update_curr() {
  310.243014 |   0)  kworker-104   |   0.190 us    |            update_min_vruntime();
  310.243015 |   0)  kworker-104   |               |            cpuacct_charge() {
  310.243015 |   0)  kworker-104   |   0.176 us    |              __rcu_read_lock();
  310.243016 |   0)  kworker-104   |   0.157 us    |              __rcu_read_unlock();
  310.243018 |   0)  kworker-104   |   2.370 us    |            }
  310.243018 |   0)  kworker-104   |   0.180 us    |            __rcu_read_lock();
  310.243019 |   0)  kworker-104   |   0.153 us    |            __rcu_read_unlock();
  310.243020 |   0)  kworker-104   |   6.974 us    |          }
  310.243021 |   0)  kworker-104   |   0.193 us    |          clear_buddies();
  310.243022 |   0)  kworker-104   |   0.164 us    |          update_cfs_group();
  310.243023 |   0)  kworker-104   | + 10.589 us   |        }
  310.243024 |   0)  kworker-104   |   0.162 us    |        hrtick_update();
  310.243025 |   0)  kworker-104   | + 12.879 us   |      }
  310.243026 |   0)  kworker-104   | + 14.158 us   |    }
  310.243026 |   0)  kworker-104   |               |    pick_next_task_fair() {
  310.243027 |   0)  kworker-104   |   0.187 us    |      check_cfs_rq_runtime();
  310.243028 |   0)  kworker-104   |               |      pick_next_entity() {
  310.243029 |   0)  kworker-104   |   0.190 us    |        clear_buddies();
  310.243030 |   0)  kworker-104   |   1.275 us    |      }
  310.243030 |   0)  kworker-104   |               |      put_prev_entity() {
  310.243031 |   0)  kworker-104   |   0.181 us    |        check_cfs_rq_runtime();
  310.243032 |   0)  kworker-104   |   1.379 us    |      }
  310.243033 |   0)  kworker-104   |   0.335 us    |      set_next_entity();
  310.243034 |   0)  kworker-104   |   7.416 us    |    }
  310.243035 |   0)  kworker-104   |               |  /* sched_switch: prev_comm=kworker/0:2 prev_pid=104 prev_prio=120 prev_state=R+ ==> next_comm=kworker/0:7 next_pid=336 next_prio=120 */
  310.243036 |   0)  kworker-104   |   0.185 us    |    enter_lazy_tlb();

And switch the context back to the first kworker:

 ------------------------------------------
 0)  kworker-104   =>  kworker-336  
 ------------------------------------------

  310.243037 |   0)  kworker-336   |               |          finish_task_switch() {
  310.243038 |   0)  kworker-336   |   0.181 us    |            preempt_count_sub();
  310.243039 |   0)  kworker-336   |   1.332 us    |          }
  310.243040 |   0)  kworker-336   |               |          /* __schedule_exit */
  310.243040 |   0)  kworker-336   |   0.248 us    |        } /* preempt_count_sub */
  310.243041 |   0)  kworker-336   | ! 889.847 us  |      } /* wake_up_worker */

After returning from wake_up_worker(); the preemption is disabled and __schedule() called again:

  310.243041 |   0)  kworker-336   | ! 892.553 us  |    } /* wq_worker_sleeping */
  310.243042 |   0)  kworker-336   |   0.181 us    |    preempt_count_add();
  310.243043 |   0)  kworker-336   |               |  /* __schedule_entry */
  310.243043 |   0)  kworker-336   |               |    rcu_note_context_switch() {
  310.243044 |   0)  kworker-336   |   0.175 us    |      rcu_sched_qs();
  310.243045 |   0)  kworker-336   |   0.174 us    |      rcu_preempt_qs();
  310.243046 |   0)  kworker-336   |   2.456 us    |    }
  310.243047 |   0)  kworker-336   |   0.188 us    |    preempt_count_add();
  310.243048 |   0)  kworker-336   |               |    update_rq_clock() {
  310.243049 |   0)  kworker-336   |   0.191 us    |      kvm_steal_clock();
  310.243050 |   0)  kworker-336   |   1.429 us    |    }
  310.243051 |   0)  kworker-336   |               |    pick_next_task_fair() {
  310.243051 |   0)  kworker-336   |               |      update_curr() {
  310.243052 |   0)  kworker-336   |   0.221 us    |        update_min_vruntime();
  310.243053 |   0)  kworker-336   |               |        cpuacct_charge() {
  310.243054 |   0)  kworker-336   |   0.191 us    |          __rcu_read_lock();
  310.243055 |   0)  kworker-336   |   0.158 us    |          __rcu_read_unlock();
  310.243056 |   0)  kworker-336   |   2.388 us    |        }
  310.243056 |   0)  kworker-336   |   0.188 us    |        __rcu_read_lock();
  310.243058 |   0)  kworker-336   |   0.154 us    |        __rcu_read_unlock();
  310.243059 |   0)  kworker-336   |   7.124 us    |      }
  310.243059 |   0)  kworker-336   |   0.200 us    |      check_cfs_rq_runtime();
  310.243060 |   0)  kworker-336   |               |      pick_next_entity() {
  310.243061 |   0)  kworker-336   |   0.192 us    |        clear_buddies();
  310.243062 |   0)  kworker-336   |   1.437 us    |      }
  310.243063 |   0)  kworker-336   | + 11.870 us   |    }
  310.243064 |   0)  kworker-336   |   0.190 us    |    preempt_count_sub();

This is the trace_prink() that shows that no context switch:

  310.243065 |   0)  kworker-336   |               |  /* oh boy, no context switch */
  310.243065 |   0)  kworker-336   |               |  /* __schedule_exit */
  310.243065 |   0)  kworker-336   |   0.216 us    |    preempt_count_sub();
  310.243067 |   0)  kworker-336   |               |    wq_worker_running() {
  310.243067 |   0)  kworker-336   |   0.214 us    |      kthread_data();
  310.243069 |   0)  kworker-336   |   1.390 us    |    }
  310.243069 |   0)  kworker-336   | ! 921.052 us  |  }

In this case, the second __schedule() is aways called in vain.

Some time ago I wrote an article about the benefits of the Red Hat Enterprise Linux for Real-time, which is our product with the PREEMPT RT patch set. Although I published it in 2016, it is still up to date! Check it out here:

The Benefits of Red Hat Enterprise Linux for Real-Time

I was able to find the slides of my first lectures, back in 2006! Most of the old slides are in pt_BR only, though. Anyways, the Lectures page is up-to-date!

I presented a workshop paper at the International Real-Time Scheduling Open Problems Seminar (RTSOPS 2018), co-located with the 30th Euromicro Conference on Real-Time Systems (ECRTS 2018). July 3, 2018, Barcelona, Spain. You can find here the Paper and the Slides.

Here is the second article about the deadline scheduler usage I wrote to LWN: Deadline scheduler part 2 — details and usage (LWN.net)

Here is the first article about the deadline scheduler usage I wrote to LWN: Deadline scheduling part 1 — overview and theory

This is the first paper of my main thesis topic, which is modeling the behavior of real-time tasks on Linux. The reference for the paper is:

D. B. de Oliveira, R. S. de Oliveira, T. Cucinotta and L. Abeni, “Automata-based modeling of interrupts in the Linux PREEMPT RT kernel,” 2017 22nd IEEE International Conference on Emerging Technologies and Factory Automation (ETFA), Limassol, 2017, pp. 1-8.

and you can find the paper at IEEExpore, or here.

Here are the slides of the Sched deadline – Open Issues lecture I gave at Linux Plumbers 2017 and at DevConf 2018.