Hello,
I am using Xen 3.3.1-rc1-pre with SEDF scheduler. From time to time the
SEDF scheduler behaves in a strange fashion: The scheduling timer
s_timer expires much to early. This causes the scheduler to run very
often and in very short distances.
The xentrace output appended to this mail shows this situation. I have
added own xentrace events ( sched-enter, do_sedf_schedule, sched_left,
sedf_wake) to the source code.
In line 17 of the xentrace output, the SEDF scheduler chooses the
idle-task to run next for maximal 45864ns (ret.time). In schedule() the
scheduling timer s_timer is then set to now+ret.time according to the
source code.
But the scheduling timer s_timer expires already after 2230ns and not as
expected after 45.864ns (line 19).
This goes on for many times.
This behaviour also appears, when dom0 or any other domU are scheduled.
Can anybody please tell me the reason for this behaviour? For me, this
behaviour is bad, because it increases latency while sending network pakets.
Thanks in advance,
Thomas
CPU0 379474998890 (+ 3601) domain_wake [ domid= 1, edomid = 0 ]
CPU0 379475000450 (+ 1560) sched_enter [ prev_domid= 32767,
now= 3173647852 ]
CPU0 379475001997 (+ 1547) sedf_do_schedule [ next_domid = 1, vcpu
= 0, ret.time= 500000 ]
CPU0 379475003349 (+ 1352) sched_switch_prev_info [ domid= 32767,
state_entry_time= 154275823 ]
CPU0 379475003960 (+ 611) sched_switch_next_info [ domid= 1,
state_entry_time= 1506, ret.time= 500000]
CPU0 379475006235 (+ 2275) __enter_scheduler [ prev<domid:edomid> =
32767 : 0, next<domid:edomid> = 1 : 0 ]
CPU0 379475010200 (+ 3965) sched_left
CPU0 379475038553 (+ 28353) do_block [ domid= 1, edomid = 0 ]
CPU0 379475039762 (+ 1209) sched_enter [ prev_domid= 1, now=
3173665971 ]
CPU0 379475042609 (+ 2847) sched_switch_prev_info [ domid= 1,
state_entry_time= 18119 ]
CPU0 379475043246 (+ 637) sched_switch_next_info [ domid= 32767,
state_entry_time= 18119, ret.time= 1000000000]
CPU0 379475044949 (+ 1703) __enter_scheduler [ prev<domid:edomid> =
1 : 0, next<domid:edomid> = 32767 : 0 ]
CPU0 379475045885 (+ 936) sched_left
CPU0 379496585884 (+21539999) t_timer_fn [ domid = 1, vcpu = 0 ]
CPU0 379496588666 (+ 2782) domain_wake [ domid= 1, edomid = 0 ]
CPU0 379496590135 (+ 1469) sched_enter [ prev_domid= 32767,
now= 3183605545 ]
CPU0 379496591500 (+ 1365) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 45864 ]
CPU0 379496592969 (+ 1469) sched_left
CPU0 379496595023 (+ 2054) s_timer_fn [ now= 3183607775 ]
CPU0 379496596557 (+ 1534) sched_enter [ prev_domid= 32767,
now= 3183608495 ]
CPU0 379496597857 (+ 1300) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 42914 ]
CPU0 379496599183 (+ 1326) sched_left
CPU0 379496600860 (+ 1677) s_timer_fn [ now= 3183610480 ]
CPU0 379496602303 (+ 1443) sched_enter [ prev_domid= 32767,
now= 3183611145 ]
CPU0 379496603447 (+ 1144) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 40264 ]
CPU0 379496604760 (+ 1313) sched_left
CPU0 379496606346 (+ 1586) s_timer_fn [ now= 3183613010 ]
CPU0 379496607789 (+ 1443) sched_enter [ prev_domid= 32767,
now= 3183613675 ]
CPU0 379496608920 (+ 1131) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 37734 ]
CPU0 379496610233 (+ 1313) sched_left
CPU0 379496612014 (+ 1781) s_timer_fn [ now= 3183615625 ]
CPU0 379496613457 (+ 1443) sched_enter [ prev_domid= 32767,
now= 3183616290 ]
CPU0 379496614588 (+ 1131) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 35119 ]
CPU0 379496615914 (+ 1326) sched_left
CPU0 379496617513 (+ 1599) s_timer_fn [ now= 3183618160 ]
CPU0 379496618956 (+ 1443) sched_enter [ prev_domid= 32767,
now= 3183618820 ]
CPU0 379496620100 (+ 1144) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 32589 ]
CPU0 379496621413 (+ 1313) sched_left
CPU0 379496622999 (+ 1586) s_timer_fn [ now= 3183620691 ]
CPU0 379496624442 (+ 1443) sched_enter [ prev_domid= 32767,
now= 3183621357 ]
CPU0 379496625560 (+ 1118) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 30052 ]
CPU0 379496626873 (+ 1313) sched_left
CPU0 379496628459 (+ 1586) s_timer_fn [ now= 3183623209 ]
CPU0 379496629902 (+ 1443) sched_enter [ prev_domid= 32767,
now= 3183623875 ]
CPU0 379496631020 (+ 1118) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 27534 ]
CPU0 379496632333 (+ 1313) sched_left
CPU0 379496633932 (+ 1599) s_timer_fn [ now= 3183625734 ]
CPU0 379496635375 (+ 1443) sched_enter [ prev_domid= 32767,
now= 3183626393 ]
CPU0 379496636493 (+ 1118) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 25016 ]
CPU0 379496637806 (+ 1313) sched_left
CPU0 379496639392 (+ 1586) s_timer_fn [ now= 3183628252 ]
CPU0 379496640835 (+ 1443) sched_enter [ prev_domid= 32767,
now= 3183628917 ]
CPU0 379496641953 (+ 1118) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 22492 ]
CPU0 379496643292 (+ 1339) sched_left
CPU0 379496644878 (+ 1586) s_timer_fn [ now= 3183630782 ]
CPU0 379496646321 (+ 1443) sched_enter [ prev_domid= 32767,
now= 3183631447 ]
CPU0 379496647439 (+ 1118) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 19962 ]
CPU0 379496648739 (+ 1300) sched_left
CPU0 379496650325 (+ 1586) s_timer_fn [ now= 3183633294 ]
CPU0 379496651768 (+ 1443) sched_enter [ prev_domid= 32767,
now= 3183633960 ]
CPU0 379496652886 (+ 1118) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 17449 ]
CPU0 379496654173 (+ 1287) sched_left
CPU0 379496655759 (+ 1586) s_timer_fn [ now= 3183635800 ]
CPU0 379496657202 (+ 1443) sched_enter [ prev_domid= 32767,
now= 3183636460 ]
CPU0 379496658320 (+ 1118) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 14949 ]
CPU0 379496659607 (+ 1287) sched_left
CPU0 379496661180 (+ 1573) s_timer_fn [ now= 3183638307 ]
CPU0 379496662597 (+ 1417) sched_enter [ prev_domid= 32767,
now= 3183638961 ]
CPU0 379496664040 (+ 1443) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 12448 ]
CPU0 379496665327 (+ 1287) sched_left
CPU0 379496666900 (+ 1573) s_timer_fn [ now= 3183640945 ]
CPU0 379496668330 (+ 1430) sched_enter [ prev_domid= 32767,
now= 3183641604 ]
CPU0 379496669422 (+ 1092) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 9805 ]
CPU0 379496670722 (+ 1300) sched_left
CPU0 379496672295 (+ 1573) s_timer_fn [ now= 3183643434 ]
CPU0 379496673725 (+ 1430) sched_enter [ prev_domid= 32767,
now= 3183644093 ]
CPU0 379496674817 (+ 1092) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 7316 ]
CPU0 379496676117 (+ 1300) sched_left
CPU0 379496677690 (+ 1573) s_timer_fn [ now= 3183645921 ]
CPU0 379496679107 (+ 1417) sched_enter [ prev_domid= 32767,
now= 3183646581 ]
CPU0 379496680238 (+ 1131) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 4828 ]
CPU0 379496681525 (+ 1287) sched_left
CPU0 379496683098 (+ 1573) s_timer_fn [ now= 3183648416 ]
CPU0 379496684515 (+ 1417) sched_enter [ prev_domid= 32767,
now= 3183649075 ]
CPU0 379496685620 (+ 1105) sedf_do_schedule [ next_domid = 32767,
vcpu = 0, ret.time= 2334 ]
CPU0 379496686920 (+ 1300) sched_left
CPU0 379496688493 (+ 1573) s_timer_fn [ now= 3183650904 ]
CPU0 379496689923 (+ 1430) sched_enter [ prev_domid= 32767,
now= 3183651564 ]
CPU0 379496692042 (+ 2119) sedf_do_schedule [ next_domid = 1, vcpu
= 0, ret.time= 500000 ]
CPU0 379496693329 (+ 1287) sched_switch_prev_info [ domid= 32767,
state_entry_time= 9985593 ]
CPU0 379496693953 (+ 624) sched_switch_next_info [ domid= 1,
state_entry_time= 47308, ret.time= 500000]
CPU0 379496696462 (+ 2509) __enter_scheduler [ prev<domid:edomid> =
32767 : 0, next<domid:edomid> = 1 : 0 ]
CPU0 379496697333 (+ 871) sched_left
CPU0 379496726011 (+ 28678) do_block [ domid= 1, edomid = 0 ]
CPU0 379496727233 (+ 1222) sched_enter [ prev_domid= 1, now=
3183668760 ]
CPU0 379496730067 (+ 2834) sched_switch_prev_info [ domid= 1,
state_entry_time= 17196 ]
CPU0 379496730691 (+ 624) sched_switch_next_info [ domid= 32767,
state_entry_time= 17196, ret.time= 1000000000]
CPU0 379496732511 (+ 1820) __enter_scheduler [ prev<domid:edomid> =
1 : 0, next<domid:edomid> = 32767 : 0 ]
CPU0 379496733421 (+ 910) sched_left
CPU0 379522057993 (+25324572) t_timer_fn [ domid = 0, vcpu = 0 ]
CPU0 379522060775 (+ 2782) domain_wake [ domid= 0, edomid = 0 ]
CPU0 379522062257 (+ 1482) sched_enter [ prev_domid= 32767,
now= 3195353894 ]
CPU0 379522063843 (+ 1586) sedf_do_schedule [ next_domid = 0, vcpu
= 0, ret.time= 15000000 ]
CPU0 379522065078 (+ 1235) sched_switch_prev_info [ domid= 32767,
state_entry_time= 11685134 ]
CPU0 379522065702 (+ 624) sched_switch_next_info [ domid= 0,
state_entry_time= 1211, ret.time= 15000000]
CPU0 379522068146 (+ 2444) __enter_scheduler [ prev<domid:edomid> =
32767 : 0, next<domid:edomid> = 0 : 0 ]
CPU0 379522071851 (+ 3705) sched_left
CPU0 379522145327 (+ 73476) do_block [ domid= 0, edomid = 0 ]
CPU0 379522146601 (+ 1274) sched_enter [ prev_domid= 0, now=
3195392772 ]
CPU0 379522149266 (+ 2665) sched_switch_prev_info [ domid= 0,
state_entry_time= 38878 ]
CPU0 379522149890 (+ 624) sched_switch_next_info [ domid= 32767,
state_entry_time= 38878, ret.time= 1000000000]
CPU0 379522151853 (+ 1963) __enter_scheduler [ prev<domid:edomid> =
0 : 0, next<domid:edomid> = 32767 : 0 ]
CPU0 379522152906 (+ 1053) sched_left
CPU0 379539357808 (+17204902) t_timer_fn [ domid = 0, vcpu = 0 ]
CPU0 379539360603 (+ 2795) domain_wake [ domid= 0, edomid = 0 ]
CPU0 379539362085 (+ 1482) sched_enter [ prev_domid= 32767,
now= 3203332991 ]
CPU0 379539363502 (+ 1417) sedf_do_schedule [ next_domid = 0, vcpu
= 0, ret.time= 15000000 ]
CPU0 379539364711 (+ 1209) sched_switch_prev_info [ domid= 32767,
state_entry_time= 7940219 ]
CPU0 379539365335 (+ 624) sched_switch_next_info [ domid= 0,
state_entry_time= 1206, ret.time= 15000000]
CPU0 379539367675 (+ 2340) __enter_scheduler [ prev<domid:edomid> =
32767 : 0, next<domid:edomid> = 0 : 0 ]
CPU0 379539368507 (+ 832) sched_left
CPU0 379539390932 (+ 22425) do_block [ domid= 0, edomid = 0 ]
CPU0 379539392206 (+ 1274) sched_enter [ prev_domid= 0, now=
3203346859 ]
CPU0 379539394286 (+ 2080) sched_switch_prev_info [ domid= 0,
state_entry_time= 13868 ]
CPU0 379539394910 (+ 624) sched_switch_next_info [ domid= 32767,
state_entry_time= 13868, ret.time= 1000000000]
CPU0 379539396821 (+ 1911) __enter_scheduler [ prev<domid:edomid> =
0 : 0, next<domid:edomid> = 32767 : 0 ]
CPU0 379539397718 (+ 897) sched_left
CPU0 379600071006 (+60673288) t_timer_fn [ domid = 0, vcpu = 0 ]
CPU0 379600073788 (+ 2782) domain_wake [ domid= 0, edomid = 0 ]
CPU0 379600075270 (+ 1482) sched_enter [ prev_domid= 32767,
now= 3231335447 ]
CPU0 379600076557 (+ 1287) sedf_do_schedule [ next_domid = 0, vcpu
= 0, ret.time= 15000000 ]
CPU0 379600078000 (+ 1443) sched_switch_prev_info [ domid= 32767,
state_entry_time= 27988588 ]
CPU0 379600078624 (+ 624) sched_switch_next_info [ domid= 0,
state_entry_time= 1242, ret.time= 15000000]
CPU0 379600081055 (+ 2431) __enter_scheduler [ prev<domid:edomid> =
32767 : 0, next<domid:edomid> = 0 : 0 ]
CPU0 379600081900 (+ 845) sched_left
CPU0 379600201877 (+ 119977) do_block [ domid= 0, edomid = 0 ]
CPU0 379600203450 (+ 1573) sched_enter [ prev_domid= 0, now=
3231394507 ]
CPU0 379600206440 (+ 2990) sched_switch_prev_info [ domid= 0,
state_entry_time= 59060 ]
CPU0 379600207142 (+ 702) sched_switch_next_info [ domid= 32767,
state_entry_time= 59060, ret.time= 1000000000]
CPU0 379600209131 (+ 1989) __enter_scheduler [ prev<domid:edomid> =
0 : 0, next<domid:edomid> = 32767 : 0 ]
CPU0 379600210483 (+ 1352) sched_left
CPU0 379712823828 (+112613345) t_timer_fn [ domid = 0, vcpu = 0 ]
CPU0 379712826961 (+ 3133) domain_wake [ domid= 0, edomid = 0 ]
CPU0 379712828560 (+ 1599) sched_enter [ prev_domid= 32767,
now= 3283339958 ]
CPU0 379712829886 (+ 1326) sedf_do_schedule [ next_domid = 0, vcpu
= 0, ret.time= 15000000 ]
CPU0 379712831199 (+ 1313) sched_switch_prev_info [ domid= 32767,
state_entry_time= 51945451 ]
CPU0 379712831823 (+ 624) sched_switch_next_info [ domid= 0,
state_entry_time= 1361, ret.time= 15000000]
CPU0 379712834228 (+ 2405) __enter_scheduler [ prev<domid:edomid> =
32767 : 0, next<domid:edomid> = 0 : 0 ]
CPU0 379712835086 (+ 858) sched_left
CPU0 379714943244 (+ 2108158) do_block [ domid= 0, edomid = 0 ]
CPU0 379714944167 (+ 923) sched_enter [ prev_domid= 0, now=
3284315810 ]
CPU0 379714946195 (+ 2028) sched_switch_prev_info [ domid= 0,
state_entry_time= 975852 ]
CPU0 379714946507 (+ 312) sched_switch_next_info [ domid= 32767,
state_entry_time= 975852, ret.time= 1000000000]
CPU0 379714947599 (+ 1092) __enter_scheduler [ prev<domid:edomid> =
0 : 0, next<domid:edomid> = 32767 : 0 ]
CPU0 379714948340 (+ 741) sched_left
CPU0 380059827862 (+344879522) t_timer_fn [ domid = 0, vcpu = 0 ]
CPU0 380059831827 (+ 3965) domain_wake [ domid= 0, edomid = 0 ]
CPU0 380059833738 (+ 1911) sched_enter [ prev_domid= 32767,
now= 3443387062 ]
CPU0 380059835220 (+ 1482) sedf_do_schedule [ next_domid = 0, vcpu
= 0, ret.time= 15000000 ]
CPU0 380059836819 (+ 1599) sched_switch_prev_info [ domid= 32767,
state_entry_time= 159071252 ]
CPU0 380059837443 (+ 624) sched_switch_next_info [ domid= 0,
state_entry_time= 1822, ret.time= 15000000]
CPU0 380059840264 (+ 2821) __enter_scheduler [ prev<domid:edomid> =
32767 : 0, next<domid:edomid> = 0 : 0 ]
CPU0 380059841174 (+ 910) sched_left
CPU0 380060181839 (+ 340665) do_block [ domid= 0, edomid = 0 ]
CPU0 380060183451 (+ 1612) sched_enter [ prev_domid= 0, now=
3443548328 ]
CPU0 380060186623 (+ 3172) sched_switch_prev_info [ domid= 0,
state_entry_time= 161266 ]
CPU0 380060187312 (+ 689) sched_switch_next_info [ domid= 32767,
state_entry_time= 161266, ret.time= 1000000000]
CPU0 380060189483 (+ 2171) __enter_scheduler [ prev<domid:edomid> =
0 : 0, next<domid:edomid> = 32767 : 0 ]
CPU0 380060190991 (+ 1508) sched_left
CPU0 380060939752 (+ 748761) domain_wake [ domid= 0, edomid = 0 ]
CPU0 380060941637 (+ 1885) sched_enter [ prev_domid= 32767,
now= 3443898063 ]
CPU0 380060943327 (+ 1690) sedf_do_schedule [ next_domid = 0, vcpu
= 0, ret.time= 500000 ]
CPU0 380060944835 (+ 1508) sched_switch_prev_info [ domid= 32767,
state_entry_time= 349735 ]
CPU0 380060945459 (+ 624) sched_switch_next_info [ domid= 0,
state_entry_time= 3201, ret.time= 500000]
CPU0 380060947474 (+ 2015) __enter_scheduler [ prev<domid:edomid> =
32767 : 0, next<domid:edomid> = 0 : 0 ]
CPU0 380060948423 (+ 949) sched_left
CPU0 380061142149 (+ 193726) do_block [ domid= 0, edomid = 0 ]
CPU0 380061143319 (+ 1170) sched_enter [ prev_domid= 0, now=
3443991084 ]
CPU0 380061146855 (+ 3536) sched_switch_prev_info [ domid= 0,
state_entry_time= 93021 ]
CPU0 380061147492 (+ 637) sched_switch_next_info [ domid= 32767,
state_entry_time= 93021, ret.time= 1000000000]
CPU0 380061149182 (+ 1690) __enter_scheduler [ prev<domid:edomid> =
0 : 0, next<domid:edomid> = 32767 : 0 ]
CPU0 380061150131 (+ 949) sched_left
CPU0 380062503574 (+ 1353443) domain_wake [ domid= 0, edomid = 0 ]
CPU0 380062505173 (+ 1599) sched_enter [ prev_domid= 32767,
now= 3444619198 ]
CPU0 380062506512 (+ 1339) sedf_do_schedule [ next_domid = 0, vcpu
= 0, ret.time= 500000 ]
CPU0 380062507773 (+ 1261) sched_switch_prev_info [ domid= 32767,
state_entry_time= 628114 ]
CPU0 380062508384 (+ 611) sched_switch_next_info [ domid= 0,
state_entry_time= 1373, ret.time= 500000]
CPU0 380062510178 (+ 1794) __enter_scheduler [ prev<domid:edomid> =
32767 : 0, next<domid:edomid> = 0 : 0 ]
CPU0 380062511023 (+ 845) sched_left
CPU0 380062601126 (+ 90103) do_block [ domid= 0, edomid = 0 ]
CPU0 380062602322 (+ 1196) sched_enter [ prev_domid= 0, now=
3444664005 ]
CPU0 380062605130 (+ 2808) sched_switch_prev_info [ domid= 0,
state_entry_time= 44807 ]
CPU0 380062605741 (+ 611) sched_switch_next_info [ domid= 32767,
state_entry_time= 44807, ret.time= 1000000000]
CPU0 380062607431 (+ 1690) __enter_scheduler [ prev<domid:edomid> =
0 : 0, next<domid:edomid> = 32767 : 0 ]
CPU0 380062608328 (+ 897) sched_left
CPU0 380062794683 (+ 186355) domain_wake [ domid= 0, edomid = 0 ]
CPU0 380062796217 (+ 1534) sched_enter [ prev_domid= 32767,
now= 3444753440 ]
CPU0 380062797452 (+ 1235) sedf_do_schedule [ next_domid = 0, vcpu
= 0, ret.time= 500000 ]
CPU0 380062798752 (+ 1300) sched_switch_prev_info [ domid= 32767,
state_entry_time= 89435 ]
CPU0 380062799350 (+ 598) sched_switch_next_info [ domid= 0,
state_entry_time= 1139, ret.time= 500000]
CPU0 380062801196 (+ 1846) __enter_scheduler [ prev<domid:edomid> =
32767 : 0, next<domid:edomid> = 0 : 0 ]
CPU0 380062802002 (+ 806) sched_left
CPU0 380063039265 (+ 237263) do_block [ domid= 0, edomid = 0 ]
CPU0 380063040682 (+ 1417) sched_enter [ prev_domid= 0, now=
3444866163 ]
CPU0 380063043711 (+ 3029) sched_switch_prev_info [ domid= 0,
state_entry_time= 112723 ]
CPU0 380063044348 (+ 637) sched_switch_next_info [ domid= 32767,
state_entry_time= 112723, ret.time= 1000000000]
CPU0 380063046129 (+ 1781) __enter_scheduler [ prev<domid:edomid> =
0 : 0, next<domid:edomid> = 32767 : 0 ]
CPU0 380063047351 (+ 1222) sched_left
CPU0 380064024353 (+ 977002) domain_wake [ domid= 0, edomid = 0 ]
CPU0 380064026030 (+ 1677) sched_enter [ prev_domid= 32767,
now= 3445320654 ]
CPU0 380064027369 (+ 1339) sedf_do_schedule [ next_domid = 0, vcpu
= 0, ret.time= 500000 ]
CPU0 380064028656 (+ 1287) sched_switch_prev_info [ domid= 32767,
state_entry_time= 454491 ]
CPU0 380064029280 (+ 624) sched_switch_next_info [ domid= 0,
state_entry_time= 1415, ret.time= 500000]
CPU0 380064030996 (+ 1716) __enter_scheduler [ prev<domid:edomid> =
32767 : 0, next<domid:edomid> = 0 : 0 ]
CPU0 380064031815 (+ 819) sched_left
CPU0 380064217663 (+ 185848) do_block [ domid= 0, edomid = 0 ]
CPU0 380064218833 (+ 1170) sched_enter [ prev_domid= 0, now=
3445409585 ]
CPU0 380064221147 (+ 2314) sched_switch_prev_info [ domid= 0,
state_entry_time= 88931 ]
CPU0 380064221758 (+ 611) sched_switch_next_info [ domid= 32767,
state_entry_time= 88931, ret.time= 1000000000]
CPU0 380064223396 (+ 1638) __enter_scheduler [ prev<domid:edomid> =
0 : 0, next<domid:edomid> = 32767 : 0 ]
CPU0 380064224371 (+ 975) sched_left
CPU0 380065515973 (+ 1291602) domain_wake [ domid= 0, edomid = 0 ]
CPU0 380065517494 (+ 1521) sched_enter [ prev_domid= 32767,
now= 3446008559 ]
CPU0 380065518755 (+ 1261) sedf_do_schedule [ next_domid = 0, vcpu
= 0, ret.time= 500000 ]
CPU0 380065520068 (+ 1313) sched_switch_prev_info [ domid= 32767,
state_entry_time= 598974 ]
CPU0 380065520692 (+ 624) sched_switch_next_info [ domid= 0,
state_entry_time= 1199, ret.time= 500000]
CPU0 380065522434 (+ 1742) __enter_scheduler [ prev<domid:edomid> =
32767 : 0, next<domid:edomid> = 0 : 0 ]
CPU0 380065523253 (+ 819) sched_left
CPU0 380065612537 (+ 89284) do_block [ domid= 0, edomid = 0 ]
CPU0 380065613681 (+ 1144) sched_enter [ prev_domid= 0, now=
3446052934 ]
CPU0 380065616047 (+ 2366) sched_switch_prev_info [ domid= 0,
state_entry_time= 44375 ]
CPU0 380065616671 (+ 624) sched_switch_next_info [ domid= 32767,
state_entry_time= 44375, ret.time= 1000000000]
CPU0 380065618231 (+ 1560) __enter_scheduler [ prev<domid:edomid> =
0 : 0, next<domid:edomid> = 32767 : 0 ]
CPU0 380065619115 (+ 884) sched_left
CPU0 380065807472 (+ 188357) domain_wake [ domid= 0, edomid = 0 ]
CPU0 380065809045 (+ 1573) sched_enter [ prev_domid= 32767,
now= 3446143023 ]
CPU0 380065810280 (+ 1235) sedf_do_schedule [ next_domid = 0, vcpu
= 0, ret.time= 500000 ]
CPU0 380065811567 (+ 1287) sched_switch_prev_info [ domid= 32767,
state_entry_time= 90089 ]
CPU0 380065812178 (+ 611) sched_switch_next_info [ domid= 0,
state_entry_time= 1175, ret.time= 500000]
CPU0 380065814141 (+ 1963) __enter_scheduler [ prev<domid:edomid> =
32767 : 0, next<domid:edomid> = 0 : 0 ]
CPU0 380065814960 (+ 819) sched_left
CPU0 380066038911 (+ 223951) do_block [ domid= 0, edomid = 0 ]
CPU0 380066040315 (+ 1404) sched_enter [ prev_domid= 0, now=
3446249696 ]
CPU0 380066043227 (+ 2912) sched_switch_prev_info [ domid= 0,
state_entry_time= 106673 ]
CPU0 380066043851 (+ 624) sched_switch_next_info [ domid= 32767,
state_entry_time= 106673, ret.time= 1000000000]
CPU0 380066045840 (+ 1989) __enter_scheduler [ prev<domid:edomid> =
0 : 0, next<domid:edomid> = 32767 : 0 ]
CPU0 380066046958 (+ 1118) sched_left
CPU0 380067037051 (+ 990093) domain_wake [ domid= 0, edomid = 0 ]
CPU0 380067038663 (+ 1612) sched_enter [ prev_domid= 32767,
now= 3446710158 ]
CPU0 380067040002 (+ 1339) sedf_do_schedule [ next_domid = 0, vcpu
= 0, ret.time= 500000 ]
CPU0 380067041276 (+ 1274) sched_switch_prev_info [ domid= 32767,
state_entry_time= 460462 ]
CPU0 380067041887 (+ 611) sched_switch_next_info [ domid= 0,
state_entry_time= 1372, ret.time= 500000]
CPU0 380067043616 (+ 1729) __enter_scheduler [ prev<domid:edomid> =
32767 : 0, next<domid:edomid> = 0 : 0 ]
CPU0 380067044435 (+ 819) sched_left
CPU0 380067229048 (+ 184613) do_block [ domid= 0, edomid = 0 ]
CPU0 380067230348 (+ 1300) sched_enter [ prev_domid= 0, now=
3446798568 ]
CPU0 380067232740 (+ 2392) sched_switch_prev_info [ domid= 0,
state_entry_time= 88410 ]
CPU0 380067233364 (+ 624) sched_switch_next_info [ domid= 32767,
state_entry_time= 88410, ret.time= 1000000000]
CPU0 380067234859 (+ 1495) __enter_scheduler [ prev<domid:edomid> =
0 : 0, next<domid:edomid> = 32767 : 0 ]
CPU0 380067235782 (+ 923) sched_left
CPU0 380068530348 (+ 1294566) domain_wake [ domid= 0, edomid = 0 ]
CPU0 380068531973 (+ 1625) sched_enter [ prev_domid= 32767,
now= 3447398903 ]
CPU0 380068533247 (+ 1274) sedf_do_schedule [ next_domid = 0, vcpu
= 0, ret.time= 500000 ]
CPU0 380068534508 (+ 1261) sched_switch_prev_info [ domid= 32767,
state_entry_time= 600335 ]
CPU0 380068535106 (+ 598) sched_switch_next_info [ domid= 0,
state_entry_time= 1218, ret.time= 500000]
CPU1 0 (+ 0) cpu_change 0x00000001
CPU1 363755445807 (+ 0) sched_enter [ prev_domid= 32767,
now= 218378482 ]
CPU1 363755448251 (+ 2444) sedf_do_schedule [ next_domid = 2, vcpu
= 0, ret.time= 500000 ]
CPU1 363755449564 (+ 1313) sched_switch_prev_info [ domid= 32767,
state_entry_time= 44550844 ]
CPU1 363755450162 (+ 598) sched_switch_next_info [ domid= 2,
state_entry_time= 2344, ret.time= 500000]
CPU1 363755453217 (+ 3055) __enter_scheduler [ prev<domid:edomid> =
32767 : 1, next<domid:edomid> = 2 : 0 ]
CPU1 363755454023 (+ 806) sched_left
CPU1 363755481141 (+ 27118) do_block [ domid= 2, edomid = 0 ]
CPU1 363755482324 (+ 1183) sched_enter [ prev_domid= 2, now=
218395342 ]
CPU1 363755484508 (+ 2184) sched_switch_prev_info [ domid= 2,
state_entry_time= 16860 ]
CPU1 363755485132 (+ 624) sched_switch_next_info [ domid= 32767,
state_entry_time= 16860, ret.time= 1000000000]
CPU1 363755486666 (+ 1534) __enter_scheduler [ prev<domid:edomid> =
2 : 0, next<domid:edomid> = 32767 : 1 ]
CPU1 363755487537 (+ 871) sched_left
CPU1 363770591483 (+15103946) sched_enter [ prev_domid= 32767,
now= 225364062 ]
CPU1 363770593875 (+ 2392) sedf_do_schedule [ next_domid = 2, vcpu
= 0, ret.time= 500000 ]
CPU1 363770595162 (+ 1287) sched_switch_prev_info [ domid= 32767,
state_entry_time= 6968720 ]
CPU1 363770595773 (+ 611) sched_switch_next_info [ domid= 2,
state_entry_time= 2105, ret.time= 500000]
CPU1 363770597814 (+ 2041) __enter_scheduler [ prev<domid:edomid> =
32767 : 1, next<domid:edomid> = 2 : 0 ]
CPU1 363770598646 (+ 832) sched_left
CPU1 363770618939 (+ 20293) do_block [ domid= 2, edomid = 0 ]
CPU1 363770620122 (+ 1183) sched_enter [ prev_domid= 2, now=
225377265 ]
CPU1 363770622358 (+ 2236) sched_switch_prev_info [ domid= 2,
state_entry_time= 13203 ]
CPU1 363770622969 (+ 611) sched_switch_next_info [ domid= 32767,
state_entry_time= 13203, ret.time= 1000000000]
CPU1 363770624503 (+ 1534) __enter_scheduler [ prev<domid:edomid> =
2 : 0, next<domid:edomid> = 32767 : 1 ]
CPU1 363770625361 (+ 858) sched_left
CPU1 363875807698 (+105182337) t_timer_fn [ domid = 2, vcpu = 0 ]
CPU1 363875810415 (+ 2717) domain_wake [ domid= 2, edomid = 0 ]
CPU1 363875811988 (+ 1573) sched_enter [ prev_domid= 32767,
now= 273894273 ]
CPU1 363875813431 (+ 1443) sedf_do_schedule [ next_domid = 2, vcpu
= 0, ret.time= 500000 ]
CPU1 363875814601 (+ 1170) sched_switch_prev_info [ domid= 32767,
state_entry_time= 48517008 ]
CPU1 363875815199 (+ 598) sched_switch_next_info [ domid= 2,
state_entry_time= 1284, ret.time= 500000]
CPU1 363875817279 (+ 2080) __enter_scheduler [ prev<domid:edomid> =
32767 : 1, next<domid:edomid> = 2 : 0 ]
CPU1 363875818085 (+ 806) sched_left
CPU1 363875837598 (+ 19513) do_block [ domid= 2, edomid = 0 ]
CPU1 363875838781 (+ 1183) sched_enter [ prev_domid= 2, now=
273906636 ]
CPU1 363875840926 (+ 2145) sched_switch_prev_info [ domid= 2,
state_entry_time= 12363 ]
CPU1 363875841550 (+ 624) sched_switch_next_info [ domid= 32767,
state_entry_time= 12363, ret.time= 1000000000]
CPU1 363875843071 (+ 1521) __enter_scheduler [ prev<domid:edomid> =
2 : 0, next<domid:edomid> = 32767 : 1 ]
CPU1 363875843942 (+ 871) sched_left
CPU1 364092898065 (+217054123) t_timer_fn [ domid = 2, vcpu = 0 ]
CPU1 364092900444 (+ 2379) domain_wake [ domid= 2, edomid = 0 ]
CPU1 364092901939 (+ 1495) sched_enter [ prev_domid= 32767,
now= 374021383 ]
CPU1 364092903343 (+ 1404) sedf_do_schedule [ next_domid = 2, vcpu
= 0, ret.time= 500000 ]
CPU1 364092904500 (+ 1157) sched_switch_prev_info [ domid= 32767,
state_entry_time= 100114747 ]
CPU1 364092905098 (+ 598) sched_switch_next_info [ domid= 2,
state_entry_time= 1128, ret.time= 500000]
CPU1 364092907191 (+ 2093) __enter_scheduler [ prev<domid:edomid> =
32767 : 1, next<domid:edomid> = 2 : 0 ]
CPU1 364092907997 (+ 806) sched_left
CPU1 364092925352 (+ 17355) do_block [ domid= 2, edomid = 0 ]
CPU1 364092926535 (+ 1183) sched_enter [ prev_domid= 2, now=
374032721 ]
CPU1 364092928589 (+ 2054) sched_switch_prev_info [ domid= 2,
state_entry_time= 11338 ]
CPU1 364092929200 (+ 611) sched_switch_next_info [ domid= 32767,
state_entry_time= 11338, ret.time= 1000000000]
CPU1 364092930721 (+ 1521) __enter_scheduler [ prev<domid:edomid> =
2 : 0, next<domid:edomid> = 32767 : 1 ]
CPU1 364092931566 (+ 845) sched_left
CPU1 364309942009 (+217010443) t_timer_fn [ domid = 2, vcpu = 0 ]
CPU1 364309944310 (+ 2301) domain_wake [ domid= 2, edomid = 0 ]
CPU1 364309945792 (+ 1482) sched_enter [ prev_domid= 32767,
now= 474127218 ]
CPU1 364309947196 (+ 1404) sedf_do_schedule [ next_domid = 2, vcpu
= 0, ret.time= 500000 ]
CPU1 364309948366 (+ 1170) sched_switch_prev_info [ domid= 32767,
state_entry_time= 100094497 ]
CPU1 364309948964 (+ 598) sched_switch_next_info [ domid= 2,
state_entry_time= 1091, ret.time= 500000]
CPU1 364309951031 (+ 2067) __enter_scheduler [ prev<domid:edomid> =
32767 : 1, next<domid:edomid> = 2 : 0 ]
CPU1 364309951837 (+ 806) sched_left
CPU1 364309968932 (+ 17095) do_block [ domid= 2, edomid = 0 ]
CPU1 364309970115 (+ 1183) sched_enter [ prev_domid= 2, now=
474138431 ]
CPU1 364309972117 (+ 2002) sched_switch_prev_info [ domid= 2,
state_entry_time= 11213 ]
CPU1 364309972728 (+ 611) sched_switch_next_info [ domid= 32767,
state_entry_time= 11213, ret.time= 1000000000]
CPU1 364309974262 (+ 1534) __enter_scheduler [ prev<domid:edomid> =
2 : 0, next<domid:edomid> = 32767 : 1 ]
CPU1 364309975120 (+ 858) sched_left
CPU1 364526985602 (+217010482) t_timer_fn [ domid = 2, vcpu = 0 ]
CPU1 364526987968 (+ 2366) domain_wake [ domid= 2, edomid = 0 ]
CPU1 364526989450 (+ 1482) sched_enter [ prev_domid= 32767,
now= 574233035 ]
CPU1 364526990854 (+ 1404) sedf_do_schedule [ next_domid = 2, vcpu
= 0, ret.time= 500000 ]
CPU1 364526992011 (+ 1157) sched_switch_prev_info [ domid= 32767,
state_entry_time= 100094604 ]
CPU1 364526992622 (+ 611) sched_switch_next_info [ domid= 2,
state_entry_time= 1109, ret.time= 500000]
CPU1 364526994832 (+ 2210) __enter_scheduler [ prev<domid:edomid> =
32767 : 1, next<domid:edomid> = 2 : 0 ]
CPU1 364526995638 (+ 806) sched_left
CPU1 364527012811 (+ 17173) do_block [ domid= 2, edomid = 0 ]
CPU1 364527013994 (+ 1183) sched_enter [ prev_domid= 2, now=
574244350 ]
CPU1 364527016022 (+ 2028) sched_switch_prev_info [ domid= 2,
state_entry_time= 11315 ]
CPU1 364527016646 (+ 624) sched_switch_next_info [ domid= 32767,
state_entry_time= 11315, ret.time= 1000000000]
CPU1 364527018167 (+ 1521) __enter_scheduler [ prev<domid:edomid> =
2 : 0, next<domid:edomid> = 32767 : 1 ]
CPU1 364527019012 (+ 845) sched_left
CPU1 364743897011 (+216877999) t_timer_fn [ domid = 2, vcpu = 0 ]
CPU1 364743899312 (+ 2301) domain_wake [ domid= 2, edomid = 0 ]
CPU1 364743900794 (+ 1482) sched_enter [ prev_domid= 32767,
now= 674277753 ]
CPU1 364743902185 (+ 1391) sedf_do_schedule [ next_domid = 2, vcpu
= 0, ret.time= 500000 ]
CPU1 364743903342 (+ 1157) sched_switch_prev_info [ domid= 32767,
state_entry_time= 100033403 ]
CPU1 364743903953 (+ 611) sched_switch_next_info [ domid= 2,
state_entry_time= 1092, ret.time= 500000]
CPU1 364743906033 (+ 2080) __enter_scheduler [ prev<domid:edomid> =
32767 : 1, next<domid:edomid> = 2 : 0 ]
CPU1 364743906839 (+ 806) sched_left
CPU1 364743924129 (+ 17290) do_block [ domid= 2, edomid = 0 ]
CPU1 364743925338 (+ 1209) sched_enter [ prev_domid= 2, now=
674289049 ]
CPU1 364743927392 (+ 2054) sched_switch_prev_info [ domid= 2,
state_entry_time= 11296 ]
CPU1 364743928003 (+ 611) sched_switch_next_info [ domid= 32767,
state_entry_time= 11296, ret.time= 1000000000]
CPU1 364743929550 (+ 1547) __enter_scheduler [ prev<domid:edomid> =
2 : 0, next<domid:edomid> = 32767 : 1 ]
CPU1 364743930408 (+ 858) sched_left
_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxxxxxxxx
http://lists.xensource.com/xen-devel
|
Home