[LITMUS^RT] Help with Understanding Scheduling Results

Geoffrey Tran gtran at isi.edu
Thu Mar 19 07:48:46 CET 2015


Hi Meng,

Sorry for the late reply.  

I didn't do the setup for the KVM instance, so I can't comment on the characteristics. I will try to find out though. I agree that if it isn't a RT scheduler, we cannot make a fair comparison. However, I mentioned it as an example of the case not occurring on a virtualized system. 

It indeed is very strange that allocating more resources to the VM makes the jobs start missing. I did try pinning VCPUs to their own dedicated PCPUs, and still see the same results.

Thanks,
Geoffrey

----- Original Message -----
From: "Meng Xu" <xumengpanda at gmail.com>
To: "Geoffrey Tran" <gtran at isi.edu>, litmus-dev at lists.litmus-rt.org
Cc: "Björn Brandenburg" <bbb at mpi-sws.org>, "Mikyung Kang" <mkkang at isi.edu>, "Stephen Crago" <crago at isi.edu>, "John Walters" <jwalters at isi.edu>
Sent: Monday, March 16, 2015 9:48:56 AM
Subject: Re: [LITMUS^RT] Help with Understanding Scheduling Results

Hi Geoffrey,

2015-03-16 15:07 GMT-04:00 Geoffrey Tran <gtran at isi.edu>:
> Hi Björn,
>
> Thanks for your reply. I've answered your questions below. I hope the formatting did not get disrupted.
>
>>----- Original Message -----
>>From: "Björn Brandenburg" <bbb at mpi-sws.org>
>>To: "Geoffrey Tran" <gtran at isi.edu>, litmus-dev at lists.litmus-rt.org
>>Cc: "Mikyung Kang" <mkkang at isi.edu>, "Stephen Crago" <crago at isi.edu>, "John Walters" <jwalters at isi.edu>
>>Sent: Thursday, March 12, 2015 5:39:09 PM
>>Subject: Re: [LITMUS^RT] Help with Understanding Scheduling Results
>>
>>
>>> On 12 Mar 2015, at 23:06, Geoffrey Tran <gtran at isi.edu> wrote:
>>>
>>> I have been working with LITMUS-RT, but have come across some weird results
>>> and was hoping someone could help clarify it please.
>>
>>Hi Geoffrey,
>>
>>thanks for your interest in LITMUS^RT. I’ve not observed any similar behavior; it indeed looks pretty strange. Some questions/comments inline below.
>>
>>>
>>> The machine used is a 16-core system.  8 cores are dedicated to the host,
>>> while up to the remainig 8 cores are used to run a Xen virtual machine.
>>> Just in case more background is needed, Xen is a popular hypervisor.  The
>>> RTDS scheduler is a new real-time scheduler that was originally the RT-Xen
>>> project.  It is now a part of the upstream Xen project.  The scheduler
>>> gives each VCPU a guaranteed capacity based on the input parameters.
>>>
>>> LITMUS-RT v2014.2 is installed in the guest.  The hypervisor is using the
>>> rtds scheduler, with each VCPU receiving the full allocation (Budget: 10000,
>>> Period: 10000).
>
>>Which LITMUS^RT scheduler are you using?
>
> We are using the GSN-EDF scheduler.
>
>>Can you reproduce the issue with LITMUS^RT running on bare metal?
>
> When running on bare metal, the issue is not observed. All jobs for each task
> meet the deadlines.
>
>>>
>>> The issue is as follows:  when running a simple two tasks with less than 50%
>>> single core utilization each (Cost=200ms, Period=500ms), jobs are still missing
>>> in certain cases.
>>> - When we use only 2VCPUs for the guest, success in all jobs is observed
>>> - When we use 3 or more VCPUs, misses are observed
>>
>>Do you use budget enforcement ?
>
> No, there is no budget enforcement. This could explain the "rollover" on
> why each missed job comes in batches, but not the reason why the first job
> missed, right?
>
>>
>>> The results from st_job_stats and an exerpt of the logs for the 3 VCPU case
>>> are below:
>>>         # Task,   Job,     Period,   Response, DL Miss?,   Lateness,  Tardiness
>>>         # task NAME=myapp PID=14442 COST=250000000 PERIOD=500000000 CPU=0
>>>          14442,     2,  500000000,      32592,        0, -499967408,          0
>>>          14442,     3,  500000000,      61805,        0, -499938195,          0
>>>          14442,     4,  500000000,  291581439,        0, -208418561,          0
>>>          14442,     5,  500000000,  251964671,        0, -248035329,          0
>>>          14442,     6,  500000000,  252424182,        0, -247575818,          0
>>>          14442,     7,  500000000,  251938074,        0, -248061926,          0
>>>          14442,     8,  500000000,  252145862,        0, -247854138,          0
>>>          14442,     9,  500000000,  251845811,        0, -248154189,          0
>>>          14442,    10,  500000000,  257706935,        0, -242293065,          0
>>>          14442,    11,  500000000,  251850581,        0, -248149419,          0
>>>          14442,    12,  500000000,  252553597,        0, -247446403,          0
>>>          14442,    13,  500000000,  251765063,        0, -248234937,          0
>>>          14442,    14,  500000000,  252902538,        0, -247097462,          0
>>>          14442,    15,  500000000, 1009091185,        1,  509091185,  509091185
>>>          14442,    16,  500000000,  760966632,        1,  260966632,  260966632
>>>          14442,    17,  500000000,  512866266,        1,   12866266,   12866266
>>>          14442,    18,  500000000,  264818921,        0, -235181079,          0
>>>          14442,    19,  500000000,  253024397,        0, -246975603,          0
>>>          14442,    20,  500000000,  252785150,        0, -247214850,          0
>>>          14442,    21,  500000000,  252466946,        0, -247533054,          0
>>>          14442,    22,  500000000, 1459862887,        1,  959862887,  959862887
>>>          14442,    23,  500000000, 1211903080,        1,  711903080,  711903080
>>>          14442,    24,  500000000,  963919848,        1,  463919848,  463919848
>>>         # task NAME=myapp PID=14443 COST=200000000 PERIOD=500000000 CPU=0
>>>          14443,     2,  500000000,      58150,        0, -499941850,          0
>>>          14443,     3,  500000000,    3202178,        0, -496797822,          0
>>>          14443,     4,  500000000,  201662924,        0, -298337076,          0
>>>          14443,     5,  500000000,  213828161,        0, -286171839,          0
>>>          14443,     6,  500000000,  202532002,        0, -297467998,          0
>>>          14443,     7,  500000000,  961643647,        1,  461643647,  461643647
>>>          14443,     8,  500000000,  663707479,        1,  163707479,  163707479
>>>          14443,     9,  500000000,  365603701,        0, -134396299,          0
>>>          14443,    10,  500000000,  201910605,        0, -298089395,          0
>>>          14443,    11,  500000000,  209025099,        0, -290974901,          0
>>>          14443,    12,  500000000,  210602663,        0, -289397337,          0
>>>          14443,    13,  500000000,  247544048,        0, -252455952,          0
>>>          14443,    14,  500000000,  459680759,        0,  -40319241,          0
>>>          14443,    15,  500000000,  202763167,        0, -297236833,          0
>>>          14443,    16,  500000000,  202368570,        0, -297631430,          0
>>>          14443,    17,  500000000,  201857551,        0, -298142449,          0
>>>          14443,    18,  500000000,  201999263,        0, -298000737,          0
>>>          14443,    19,  500000000,  958909178,        1,  458909178,  458909178
>>>          14443,    20,  500000000,  660591085,        1,  160591085,  160591085
>>>          14443,    21,  500000000,  362025653,        0, -137974347,          0
>>>          14443,    22,  500000000,  202565748,        0, -297434252,          0
>>>          14443,    23,  500000000,  202456104,        0, -297543896,          0
>>>          14443,    24,  500000000,  202528628,        0, -297471372,          0
>>>
>>>          .....
>>>         [ 328638446] RELEASE        14443/14    on CPU  0 328638946.00ms
>>>         [ 328638446] RELEASE        14442/14    on CPU  1 328638946.00ms
>>>         [ 328638446] SWITCH_TO      14442/14    on CPU  0
>>>         [ 328638698] SWITCH_FROM    14442/14    on CPU  0
>>>         [ 328638698] COMPLETION     14442/14    on CPU  0
>>>         [ 328638704] SWITCH_TO      14443/14    on CPU  1
>>>         [ 328638905] SWITCH_FROM    14443/14    on CPU  1
>>>         [ 328638905] COMPLETION     14443/14    on CPU  1
>>>         [ 328638946] RELEASE        14442/15    on CPU  0 328639446.00ms
>>>         [ 328638946] RELEASE        14443/15    on CPU  1 328639446.00ms
>>>         [ 328638946] SWITCH_TO      14443/15    on CPU  0
>>>         [ 328639148] SWITCH_FROM    14443/15    on CPU  0
>>>         [ 328639148] COMPLETION     14443/15    on CPU  0
>>>         [ 328639446] RELEASE        14443/16    on CPU  0 328639946.00ms
>>>         [ 328639446] RELEASE        14442/16    on CPU  1 328639946.00ms
>>
>>Random observation: the next release of 14443 happens on CPU 0, whereas 14442 is still being released on CPU 1. This means CPU 1 must have set a timer for the release to occur. Usually, it shouldn’t do that unless it either (a) processed a completion or (b) prevented a budget overrun. Either event should have left a trace record (I think). Are you sure the trace is complete (i.e., no missing writes)?
>>
>
> Yes, as far as I know, there were no reported failed writes at the completion of the tracing.
>
>>
>>>         [ 328639446] SWITCH_TO      14443/16    on CPU  0
>>>         [ 328639648] SWITCH_FROM    14443/16    on CPU  0
>>>         [ 328639648] COMPLETION     14443/16    on CPU  0
>>>         [ 328639703] SWITCH_TO      14442/15    on CPU  1
>>>         [ 328639946] RELEASE        14442/17    on CPU  1 328640446.00ms
>>>         [ 328639946] RELEASE        14443/17    on CPU  0 328640446.00ms
>>>         [ 328639946] SWITCH_TO      14443/17    on CPU  0
>>>         [ 328639955] SWITCH_FROM    14442/15    on CPU  1
>>>         [ 328639955] COMPLETION     14442/15    on CPU  1
>>>         [ 328639955] SWITCH_TO      14442/16    on CPU  1
>>>         [ 328640147] SWITCH_FROM    14443/17    on CPU  0
>>>         [ 328640147] COMPLETION     14443/17    on CPU  0
>>>         [ 328640206] SWITCH_FROM    14442/16    on CPU  1
>>>         [ 328640206] COMPLETION     14442/16    on CPU  1
>>>         [ 328640206] SWITCH_TO      14442/17    on CPU  1
>>>         .....
>>>
>>>
>>> It is interesting to note that when both job 15's are released, the job for PID 14443 is
>>> allowed to run. however, for PID 14442, the job does not run until the next period!
>>>
>>> It has also been observed that running two tasks on a guest with 8 VCPUs sees the same
>>> task misses.  But by artificailly loading the system by running 6 instances of "yes >
>>> /dev/null", all jobs meet their deadlines.
>>
>>Do these instances of yes run as LITMUS^RT tasks or just as regular SCHED_OTHER tasks?
>
> The instances of yes run as regular tasks.  I just launched them from the shell without any calls to liblitmus.
>
>>
>>Also, can you provide matching output of the debug trace log (the TRACE() stream)?
>
> I've attached two text documents containing the output from st_job_stats followed by the
> trace logs you've requested. One is for the bare-metal case, one is for the VM. Sorry,
> we don't have the logs for that exact run available, but this is from a run with the
> same parameters. The bare metal case is a bit cluttered due to the current system having
> the preemption tracing enabled.
>
>>
>>I’ve not used LITMUS^RT on Xen. I don’t mean to blame Xen, but it would make it easier to for us if you could reproduce this behavior on bare metal.
>
> Again, thanks for your help and comments so far!
>
> To provide a little bit of context, We're virtualizing in this case because it
> looks to be a very interesting area.  The weirdness that we are observing is the
> fact that the above issues do not occur on bare-metal.  It is very odd becase we
> do not observe this on KVM either.

How did you configure the KVM? I'm not sure if KVM has the real-time
scheduler or not. If not, it will not be an apple-to-apple comparison.
(I'm not trying to defend Xen, I'm just trying to figure out what is
going wrong.)

>>> The issue is as follows:  when running a simple two tasks with less than 50%
>>> single core utilization each (Cost=200ms, Period=500ms), jobs are still missing
>>> in certain cases.
>>> - When we use only 2VCPUs for the guest, success in all jobs is observed
>>> - When we use 3 or more VCPUs, misses are observed

The weird thing is why allocating more resource to the VM make the
schedulable taskset unschedulable? This is more like a scheduling
anomaly.

Is it possible that the release timer is configured on VCPU 1, but
VCPU 1 is scheduled out right before the release timer will be
triggered. This will cause the release delay.  In addition, if you
just dedicate a cpu to a VCPU and does not allow that cpu to run any
other VCPUs, will the same weird situation happen?

Thanks,

Meng



-- 


-----------
Meng Xu
PhD Student in Computer and Information Science
University of Pennsylvania




More information about the litmus-dev mailing list