WARNING - OLD ARCHIVES

This is an archived copy of the Xen.org mailing list, which we have preserved to ensure that existing links to archives are not broken. The live archive, which contains the latest emails, can be found at http://lists.xen.org/
   
 
 
Xen 
 
Home Products Support Community News
 
   
 

xen-devel

[Xen-devel] strange behaviour of SEDF's scheduling timer

To: xen-devel@xxxxxxxxxxxxxxxxxxx
Subject: [Xen-devel] strange behaviour of SEDF's scheduling timer
From: Thomas <thomas.pfeuffer@xxxxxxxx>
Date: Mon, 09 Mar 2009 14:41:54 +0100
Delivery-date: Mon, 09 Mar 2009 06:42:50 -0700
Envelope-to: www-data@xxxxxxxxxxxxxxxxxxx
List-help: <mailto:xen-devel-request@lists.xensource.com?subject=help>
List-id: Xen developer discussion <xen-devel.lists.xensource.com>
List-post: <mailto:xen-devel@lists.xensource.com>
List-subscribe: <http://lists.xensource.com/mailman/listinfo/xen-devel>, <mailto:xen-devel-request@lists.xensource.com?subject=subscribe>
List-unsubscribe: <http://lists.xensource.com/mailman/listinfo/xen-devel>, <mailto:xen-devel-request@lists.xensource.com?subject=unsubscribe>
Sender: xen-devel-bounces@xxxxxxxxxxxxxxxxxxx
User-agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.7.8) Gecko/20050603 Fedora/1.7.8-1.1.1.legacy
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
<Prev in Thread] Current Thread [Next in Thread>
  • [Xen-devel] strange behaviour of SEDF's scheduling timer, Thomas <=