<html><head><meta http-equiv="Content-Type" content="text/html charset=windows-1252"></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space; "><br><div><div>On Sep 15, 2012, at 12:17 PM, Glenn Elliott <<a href="mailto:gelliott@cs.unc.edu">gelliott@cs.unc.edu</a>> wrote:</div><br class="Apple-interchange-newline"><blockquote type="cite"><meta http-equiv="Content-Type" content="text/html charset=iso-8859-1"><div style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space; "><br><div><div>On Sep 14, 2012, at 8:21 PM, Jonathan Herman <<a href="mailto:hermanjl@cs.unc.edu">hermanjl@cs.unc.edu</a>> wrote:</div><div><br></div><blockquote type="cite"><br>On Fri, Sep 14, 2012 at 7:57 PM, Glenn Elliott <<a href="mailto:gelliott@cs.unc.edu">gelliott@cs.unc.edu</a>> wrote:<br><blockquote type="cite">Well, I am stuck in a strange case where a task is linked but never<br>scheduled (G-EDF):<br><br>3903 P0 [check_for_preemptions@litmus/sched_gsn_edf.c:365]:<br>check_for_preemptions: attempting to link task 1795 to 0<br>3904 P0 [gsnedf_get_nearest_available_cpu@litmus/sched_gsn_edf.c:347]: Could<br>not find an available CPU close to P0<br>3905 P0 [__add_ready@litmus/rt_domain.c:312]: rt: adding aux_threads/1799<br>(0, 4611686018427387903, 4611686018427387903) [inh_task: (nil)/0 (0, 0 0)]<br>rel=59812157846 to ready queue at 60312058176<br>3907 P0 [link_task_to_cpu@litmus/sched_gsn_edf.c:218]: (aux_threads/1799:1)<br>linked = aux_threads/1795<br>3908 P0 [link_task_to_cpu@litmus/sched_gsn_edf.c:219]: (aux_threads/1799:1)<br>entry->linked = aux_threads/1799<br>3909 P0 [link_task_to_cpu@litmus/sched_gsn_edf.c:261]: (aux_threads/1795:2)<br>linked to 0.<br>3914 P1 [gsnedf_tick@litmus/sched_gsn_edf.c:472]: (aux_threads/1796:1) tick<br>3915 P2 [gsnedf_tick@litmus/sched_gsn_edf.c:472]: (aux_threads/1797:1) tick<br>3916 P3 [gsnedf_tick@litmus/sched_gsn_edf.c:472]: (aux_threads/1798:1) tick<br>3917 P0 [gsnedf_tick@litmus/sched_gsn_edf.c:472]: (aux_threads/1799:1) tick<br>3918 P1 [gsnedf_tick@litmus/sched_gsn_edf.c:472]: (aux_threads/1796:1) tick<br>3919 P2 [gsnedf_tick@litmus/sched_gsn_edf.c:472]: (aux_threads/1797:1) tick<br>3920 P3 [gsnedf_tick@litmus/sched_gsn_edf.c:472]: (aux_threads/1798:1) tick<br>3921 P0 [gsnedf_tick@litmus/sched_gsn_edf.c:472]: (aux_threads/1799:1) tick<br>3922 P1 [gsnedf_tick@litmus/sched_gsn_edf.c:472]: (aux_threads/1796:1) tick<br>3923 P2 [gsnedf_tick@litmus/sched_gsn_edf.c:472]: (aux_threads/1797:1) tick<br>3924 P3 [gsnedf_tick@litmus/sched_gsn_edf.c:472]: (aux_threads/1798:1) tick<br>3925 P0 [gsnedf_tick@litmus/sched_gsn_edf.c:472]: (aux_threads/1799:1) tick<br>3926 P1 [gsnedf_tick@litmus/sched_gsn_edf.c:472]: (aux_threads/1796:1) tick<br>3927 P2 [gsnedf_tick@litmus/sched_gsn_edf.c:472]: (aux_threads/1797:1) tick<br>3928 P3 [gsnedf_tick@litmus/sched_gsn_edf.c:472]: (aux_threads/1798:1) tick<br><br><br>I updated gsnedf_tick to print the currently scheduled real-time task. Task<br>1795 should be running on P0 instead of 1799.<br><br>Has anyone ever seen something like this before?<br><br>Thanks,<br>Glenn<br><br>p.s. Ignore the crazy period/relative_deadline for 1799. Those are just<br>place holders. 1799 is really just a worker thread that has a statically<br>low priority and should only run when the system is idle (or according to an<br>inherited priority).<br><br>p.p.s. I think there is a bug in litmus.c::litmus_fork(). is_realtime() is<br>returning false for forked children of a real-time task (expected), so the<br>fork-copied rt_param state is not reset. Thus, the child gets the same<br>rt_params as the parent. This is probably harmless if we're sure to re-init<br>any children that transition to real-time. However, for the sake of<br>completeness, I wonder if we should execute "reinit_litmus_state(p,0);" for<br>all children. I am doing some where tasks are forced to become real-time<br>from within the kernel (worker threads), and this possible bug bit me.<br><br>_______________________________________________<br>litmus-dev mailing list<br><a href="mailto:litmus-dev@lists.litmus-rt.org">litmus-dev@lists.litmus-rt.org</a><br><a href="https://lists.litmus-rt.org/listinfo/litmus-dev">https://lists.litmus-rt.org/listinfo/litmus-dev</a><br><br></blockquote><br>I would bet cashmoney that your task is not preemptable. Your</blockquote><blockquote type="cite">check_for_preempt calls preempt()->preempt_if_preemptable after<br>linking the task, which calls litmus_reschedule if the task is not<br>preemptable. litmus_reschedule ALWAYS hits line 98 of your preempt.c<br>and traces state.</blockquote><blockquote type="cite"><br>-- <br>Jonathan Herman<br>Department of Computer Science at UNC Chapel Hill<br></blockquote><br></div><div><br></div><div><div>I think something else could be going wrong. I believe the task is preemptible. litmus_reschedule() is indeed being called. Here's the code, with some trace statements added in. I've put the code path that is being followed in bold.</div><div><br></div><div><div> 66 void litmus_reschedule(int cpu)</div><div> 67 {</div><div> 68 int picked_transition_ok = 0;</div><div> 69 int scheduled_transition_ok = 0;</div><div> 70 </div><div> 71 /* The (remote) CPU could be in any state. */</div><div> 72 </div><div> 73 /* The critical states are TASK_PICKED and TASK_SCHEDULED, as the CPU</div><div> 74 * is not aware of the need to reschedule at this point. */</div><div> 75 </div><div> 76 /* is a context switch in progress? */</div><div><b> 77 if (cpu_is_in_sched_state(cpu, TASK_PICKED)) {</b></div><div><b> 78 picked_transition_ok = sched_state_transition_on(</b></div><div><b> 79 cpu, TASK_PICKED, PICKED_WRONG_TASK);</b></div><div><b> 80 </b></div><div><b> 81 TRACE_CUR("cpu %d: picked_transition_ok = %d\n", cpu, picked_transition_ok);</b></div><div> 82 }</div><div> 83 else {</div><div> 84 TRACE_CUR("cpu %d: picked_transition_ok = 0 (static)\n", cpu);</div><div> 85 }</div><div> 86 </div><div> 87 if (!picked_transition_ok &&</div><div> 88 cpu_is_in_sched_state(cpu, TASK_SCHEDULED)) {</div><div> 89 /* We either raced with the end of the context switch, or the</div><div> 90 * CPU was in TASK_SCHEDULED anyway. */</div><div> 91 scheduled_transition_ok = sched_state_transition_on(</div><div> 92 cpu, TASK_SCHEDULED, SHOULD_SCHEDULE);</div><div> 93 TRACE_CUR("cpu %d: scheduled_transition_ok = %d\n", cpu, scheduled_transition_ok);</div><div> 94 }</div><div><b> 95 else {</b></div><div><b> 96 TRACE_CUR("cpu %d: scheduled_transition_ok = 0 (static)\n", cpu);</b></div><div><b> 97 }</b></div><div> 98 </div><div> 99 /* If the CPU was in state TASK_SCHEDULED, then we need to cause the</div><div>100 * scheduler to be invoked. */</div><div>101 if (scheduled_transition_ok) {</div><div>102 if (smp_processor_id() == cpu) {</div><div>103 set_tsk_need_resched(current);</div><div>104 }</div><div>105 else {</div><div>106 smp_send_reschedule(cpu);</div><div>107 }</div><div>108 }</div><div>109 </div><div>110 TRACE_STATE("%s picked-ok:%d sched-ok:%d\n",</div><div>111 __FUNCTION__,</div><div>112 picked_transition_ok,</div><div>113 scheduled_transition_ok);</div><div>114 }</div><div><br></div></div><div>Trace output:</div><div><div>3956 P1 [link_task_to_cpu@litmus/sched_gsn_edf.c:218]: (aux_threads/1820:1) linked = aux_threads/1816</div><div>3957 P1 [link_task_to_cpu@litmus/sched_gsn_edf.c:219]: (aux_threads/1820:1) entry->linked = aux_threads/1820</div><div>3958 P1 [link_task_to_cpu@litmus/sched_gsn_edf.c:261]: (aux_threads/1816:2) linked to 1. </div><div>3962 P1 [preempt_if_preemptable@litmus/sched_plugin.c:36]: (aux_threads/1820:1) preempt_if_preemptable: aux_threads/1820</div><div>3963 P1 [preempt_if_preemptable@litmus/sched_plugin.c:45]: (aux_threads/1820:1) preempt local cpu.</div><div>3964 P1 [preempt_if_preemptable@litmus/sched_plugin.c:71]: (aux_threads/1820:1) calling litmus_reschedule()</div><div><b>3965 P1 [litmus_reschedule@litmus/preempt.c:81]: (aux_threads/1820:1) cpu 1: picked_transition_ok = 1</b></div><div><b>3966 P1 [litmus_reschedule@litmus/preempt.c:96]: (aux_threads/1820:1) cpu 1: scheduled_transition_ok = 0 (static)</b></div><div>3968 P1 [gsnedf_tick@litmus/sched_gsn_edf.c:474]: (aux_threads/1820:1) tick 67358153479</div><div>3972 P1 [gsnedf_tick@litmus/sched_gsn_edf.c:474]: (aux_threads/1820:1) tick 67359153359</div><div><br></div></div><div><br></div><div><br></div><div>So it looks like my linked task is not scheduled because the CPU state is TASK_PICKED and picked_transition_ok is set to 1. I've never worked with this part of Litmus before, so I don't know what is "normal." Is there supposed to be some sort of deferred safety-net that will schedule the linked task when picked_transition_ok==1 that is not being invoked?</div><div><br></div><div>-Glenn</div><div><br></div></div></div></blockquote><br></div><div><br></div><div>Following up, is there any way that a task could be scheduled while the CPU state remains TASK_PICKED? Thread 1785 calls job_completion() on P0. 1789 is linked as the next task to run on P0 and the state of changes from WILL_SCHEDULE to TASK_PICKED. As I understand it, the state of P0 should soon switch to TASK_SCHEDULED when kernel/sched.c::schedule() calls sched_state_validate_switch(). However, I'm not sure that this is ever being called. As you see in the log below, gsnedf_tick() on P0 shows that 1789 is indeed scheduled, but the state of P0 never switched to TASK_SCHEDULED. Is this the correct behavior? I believe what may be happening is that P0 has an incorrect state; thus, when I try to link a new task to P0, the state transitions from TASK_PICKED to PICKED_WRONG_TASK. Note that 1789 is in a user-space busy-wait loop, so it will never yield the processor-- it must always be preempted.</div><div><br></div><div><div>91576 P0 [gsnedf_schedule@litmus/sched_gsn_edf.c:857]: (aux_threads/1785:1) blocks:0 out_of_time:0 signal_budget: 0 np:0 sleep:1 preempt:0 state:0 sig:0 </div><div><b>91577 P0 [job_completion@litmus/sched_gsn_edf.c:423]: (aux_threads/1785:1) job_completion(). // 1785 calls job_completion() and wants to give up P0.</b></div><div>91578 P0 [link_task_to_cpu@litmus/sched_gsn_edf.c:218]: (aux_threads/1785:2) linked = (nil)/0</div><div>91579 P0 [link_task_to_cpu@litmus/sched_gsn_edf.c:219]: (aux_threads/1785:2) entry->linked = aux_threads/1785</div><div>91580 P0 [link_task_to_cpu@litmus/sched_gsn_edf.c:263]: NULL linked to 0. </div><div>91583 P0 [__add_release@litmus/rt_domain.c:353]: (aux_threads/1785:2) add_release(), rel=62349575697</div><div>91584 P0 [check_for_preemptions@litmus/sched_gsn_edf.c:365]: check_for_preemptions: attempting to link task 1789 to 0</div><div>91585 P0 [gsnedf_get_nearest_available_cpu@litmus/sched_gsn_edf.c:347]: P0 is closest available CPU to P0 </div><div>91586 P0 [link_task_to_cpu@litmus/sched_gsn_edf.c:218]: (aux_threads/1785:2) linked = aux_threads/1789</div><div>91587 P0 [link_task_to_cpu@litmus/sched_gsn_edf.c:219]: (aux_threads/1785:2) entry->linked = (nil)/0</div><div><b>91588 P0 [link_task_to_cpu@litmus/sched_gsn_edf.c:261]: (aux_threads/1789:1) linked to 0. // 1789 linked to P0</b></div><div>91593 P0 [preempt_if_preemptable@litmus/sched_plugin.c:36]: (aux_threads/1785:2) preempt_if_preemptable: aux_threads/1785</div><div>91594 P0 [preempt_if_preemptable@litmus/sched_plugin.c:45]: (aux_threads/1785:2) preempt local cpu.</div><div>91595 P0 [preempt_if_preemptable@litmus/sched_plugin.c:72]: (aux_threads/1785:2) calling litmus_reschedule()</div><div>91596 P0 [litmus_reschedule@litmus/preempt.c:84]: (aux_threads/1785:2) cpu 0: picked_transition_ok = 0 (static)</div><div>91597 P0 [litmus_reschedule@litmus/preempt.c:96]: (aux_threads/1785:2) cpu 0: scheduled_transition_ok = 0 (static)</div><div>91598 P0 [litmus_reschedule@litmus/preempt.c:113]: SCHED_STATE litmus_reschedule picked-ok:0 sched-ok:0</div><div>91600 P0 [gsnedf_schedule@litmus/sched_gsn_edf.c:914]: (aux_threads/1789:1) scheduled_on = P0</div><div>91601 P0 [gsnedf_schedule@litmus/sched_gsn_edf.c:919]: (aux_threads/1785:2) scheduled_on = NO_CPU</div><div><b>91602 P0 [set_sched_state@include/litmus/preempt.h:75]: SCHED_STATE [P0] 0x4 (WILL_SCHEDULE) -> 0x8 (TASK_PICKED) // 1789 picked to run.</b></div><div><b>91603 P0 [gsnedf_tick@litmus/sched_gsn_edf.c:474]: (aux_threads/1789:1) tick 61850029047 // 1789 is scheduled, but P0 has not transitioned to TASK_SCHEDULED</b></div><div>91604 P1 [gsnedf_tick@litmus/sched_gsn_edf.c:474]: (aux_threads/1786:1) tick 61850150117</div><div>91605 P2 [gsnedf_tick@litmus/sched_gsn_edf.c:474]: (aux_threads/1787:1) tick 61850278487</div><div>91606 P3 [gsnedf_tick@litmus/sched_gsn_edf.c:474]: (aux_threads/1788:1) tick 61850399157</div><div><b>91607 P0 [gsnedf_tick@litmus/sched_gsn_edf.c:474]: (aux_threads/1789:1) tick 61851025147 // 1789 still scheduled. Still no transition.</b></div><div>91608 P1 [gsnedf_tick@litmus/sched_gsn_edf.c:474]: (aux_threads/1786:1) tick 61851149077</div><div>91609 P2 [gsnedf_tick@litmus/sched_gsn_edf.c:474]: (aux_threads/1787:1) tick 61851278397</div><div><br></div></div><div>… lots and lots of ticks …</div><div><br></div><div><div><b>93599 P0 [gsnedf_tick@litmus/sched_gsn_edf.c:474]: (aux_threads/1789:1) tick 62349024417 // 1789 still ticking on P0</b></div><div>93600 P1 [gsnedf_tick@litmus/sched_gsn_edf.c:474]: (aux_threads/1786:1) tick 62349148547</div><div>93601 P2 [gsnedf_tick@litmus/sched_gsn_edf.c:474]: (aux_threads/1787:1) tick 62349278407</div><div>93602 P3 [gsnedf_tick@litmus/sched_gsn_edf.c:474]: (aux_threads/1788:1) tick 62349398267</div><div><b>93603 P0 [gsnedf_release_jobs@litmus/sched_gsn_edf.c:401]: (aux_threads/1789:1) gsnedf_release_jobs // new higher prio job (1785) released</b></div><div>93606 P0 [check_for_preemptions@litmus/sched_gsn_edf.c:365]: check_for_preemptions: attempting to link task 1785 to 0</div><div>93607 P0 [gsnedf_get_nearest_available_cpu@litmus/sched_gsn_edf.c:347]: Could not find an available CPU close to P0</div><div>93608 P0 [__add_ready@litmus/rt_domain.c:312]: rt: adding aux_threads/1789 (0, 4611686018427387903, 4611686018427387903) [inh_task: (nil)/0 (0, 0 0)] rel=61849803767 to ready queue at 62349602827</div><div>93610 P0 [link_task_to_cpu@litmus/sched_gsn_edf.c:218]: (aux_threads/1789:1) linked = aux_threads/1785</div><div><b>93611 P0 [link_task_to_cpu@litmus/sched_gsn_edf.c:219]: (aux_threads/1789:1) entry->linked = aux_threads/1789</b></div><div><b>93612 P0 [link_task_to_cpu@litmus/sched_gsn_edf.c:261]: (aux_threads/1785:2) linked to 0.</b></div><div>93616 P0 [preempt_if_preemptable@litmus/sched_plugin.c:36]: (aux_threads/1789:1) preempt_if_preemptable: aux_threads/1789</div><div>93617 P0 [preempt_if_preemptable@litmus/sched_plugin.c:45]: (aux_threads/1789:1) preempt local cpu.</div><div>93618 P0 [preempt_if_preemptable@litmus/sched_plugin.c:72]: (aux_threads/1789:1) calling litmus_reschedule()</div><div><b>93619 P0 [sched_state_transition_on@include/litmus/preempt.h:99]: SCHED_STATE [P0] 0x8 (TASK_PICKED) -> 0x10 (PICKED_WRONG_TASK) // SCHED_STATE of P0 bad? Shouldn't it have been TASK_SCHEDULED?</b></div><div>93620 P0 [litmus_reschedule@litmus/preempt.c:81]: (aux_threads/1789:1) cpu 0: picked_transition_ok = 1</div><div>93621 P0 [litmus_reschedule@litmus/preempt.c:96]: (aux_threads/1789:1) cpu 0: scheduled_transition_ok = 0 (static)</div><div>93622 P0 [litmus_reschedule@litmus/preempt.c:113]: SCHED_STATE litmus_reschedule picked-ok:1 sched-ok:0</div><div>93623 P0 [__edf_higher_prio@litmus/edf_common.c:95]: (aux_threads/1789:1) aux_threads/1789 >> aux_threads/1788 --- 0</div><div><b>93624 P0 [gsnedf_tick@litmus/sched_gsn_edf.c:474]: (aux_threads/1789:1) tick 62350024927 // 1789 still ticking away. >:(</b></div><div>93625 P1 [gsnedf_tick@litmus/sched_gsn_edf.c:474]: (aux_threads/1786:1) tick 62350149077</div></div><br></body></html>