Why vruntime of a running process is decreased in CFS scheduler in linux?

462 Views Asked by At

I was exploring CFS scheduler. As per CFS, vruntime is the amount of time a process runs on a CPU. So, once a process consumes some CPU its vruntime is increased.

To understand the context_switch concept in depth, I looked into context_switch method implementation of kernel/sched/core.c file.

context_switch(struct rq *rq, struct task_struct *prev,
           struct task_struct *next)

To know the processes involved into context-switch -especially to know which process scheduled out and which process scheduled in , I have added

trace_printk(KERN_INFO "**$$,traceme,%d,%llu,%llu,%d,%llu,%llu\n", (int)(prev->pid),prev->se.vruntime,prev->se.sum_exec_runtime, (int)(next->pid),next->se.vruntime,next->se.sum_exec_runtime);

inside context_switch() function of kernel/sched/core.c file.

Some sample data after cleaning up

//(prev->pid),prev->se.vruntime,prev->se.sum_exec_runtime, (int)(next->pid),next->se.vruntime,next->se.sum_exec_runtime



 Line-1 :    7560,24498429469681,823155565,7566,24498418258892,1637962
 Line-2 :    7566,24498418261234,1640304,7580,24498417733416,1018016
 Line-3 :    7580,24498417752807,1037407,686,24498429468802,48339928895
 Line-4 :    686,24498429469817,48339929910,7566,24498418261234,1640304
 Line-5 :    7566,24498418263610,1642680,7581,24498417762357,1038126
 Line-6 :    7581,24498417781339,1057108,7560,24498429469681,823155565

 Line-7 :    7560,24498429470724,823156608,7566,24498418263610,1642680
 Line-8 :    7566,24498418265980,1645050,7582,24498418395747,1202608
 Line-9 :    7582,24498418414400,1221261,686,24498429469817,48339929910
 Line-10:    686,24498429470804,48339930897,7566,24498418265980,1645050
 Line-11:    7566,24498418268334,1647404,7583,24498417826636,1168325
 Line-12:    7583,24498417845297,1186986,7560,24498429470724,823156608

 Line-13:    7560,24498429471802,823157686,7566,24498418268334,1647404
 Line-14:    7566,24498418270800,1649870,686,24498429470804,48339930897
 // Up to this line vruntime of all process increased in each run as expected.


 Line-15: 686,24498438028365,48348488458,7560,24498429471802,823157686
 Line-16: 0,0,0,7,918077230457,2930949708
 Line-17: 7,918077232097,2930951348,0,0,0
 Line-18: 7560,6056741110796,823305719,7584,24498429478909,1156272 <---- Here vruntime of process 7560 is decreased . Why?

From the above data,we can deduce how much time each process executed before being scheduled out.

p_pid   p_vrt         p_sum_exe_rt   n_pid    n_vrt     n_sum_exe_rt                 |  prev_tslice next_tslice  CPU
 7560 ,  24498429469681,       823155565,   7566 ,  24498418258892,        1637962, | ,       1191 ,      2327 
  7566 ,  24498418261234,         1640304,   7580 ,  24498417733416,        1018016, | ,       2342 ,     19462 
  7580 ,  24498417752807,         1037407,    686 ,  24498429468802,    48339928895, | ,      19391 ,      1003 
   686 ,  24498429469817,     48339929910,   7566 ,  24498418261234,        1640304, | ,       1015 ,      2342 
  7566 ,  24498418263610,         1642680,   7581 ,  24498417762357,        1038126, | ,       2376 ,     18429 
  7581 ,  24498417781339,         1057108,   7560 ,  24498429469681,      823155565, | ,      18982 ,      1191 

  7560 ,  24498429470724,       823156608,   7566 ,  24498418263610,        1642680, | ,       1043 ,      2376 
  7566 ,  24498418265980,         1645050,   7582 ,  24498418395747,        1202608, | ,       2370 ,     19520 
  7582 ,  24498418414400,         1221261,    686 ,  24498429469817,    48339929910, | ,      18653 ,      1015 
   686 ,  24498429470804,     48339930897,   7566 ,  24498418265980,        1645050, | ,        987 ,      2370 
  7566 ,  24498418268334,         1647404,   7583 ,  24498417826636,        1168325, | ,       2354 ,     19617 
  7583 ,  24498417845297,         1186986,   7560 ,  24498429470724,      823156608, | ,      18661 ,      1043 
  7560 ,  24498429471802,       823157686,   7566 ,  24498418268334,        1647404, | ,       1078 ,      2354 


   7566 ,  24498418270800,         1649870,    686 ,  24498429470804,    48339930897, | ,       2466 ,       987 



   686 ,  24498438028365,     48348488458,   7560 ,  24498429471802,      823157686, | ,    8557561 ,      1078 
 //----------------------- Up to this line vruntime is increased      
   7560 ,   6056741110796,       823305719,   7584 ,  24498429478909,        1156272, | ,     148033 ,     18671 

Everything looks perfect - vruntime of a process increased with every run.

To my surprise in the last line, vruntime of a running process is decreased.

  1. vruntime of process with pid 7560 is decreased (from 24498429471802 to 6056741110796 ) in last line - Why ?

  2. How is it possible vruntime of a running process is decreased even when the process is pinned to a particular CPU core (so no chance of migration to other CPU Core)?

  3. Another important observation, in other run 7560 process run for shorter time slice, but this last time it gets higher timeslice. Any co-relation between larger time slice and reduction in vruntime ?

I am using Debian 8.0 and Ubuntu 16.04, Kernel 3.16.35 and this happened in both OS.

Any links to understand the reason will be a great help.

0

There are 0 best solutions below