Permalink
Browse files

[Experimentation component]

* earliest_deadline_first/README: Explain the new experimentation result.
* earliest_deadline_first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem:
Add new experimentation result.
* earliest_deadline_first/006-detect_potential_outdated_rq_clock.sh: New.
* earliest_deadline_first/process_experiment_result.sh: New.
* earliest_deadline_first/run_experiment.sh: New.
* earliest_deadline_first/sched_dl_instrumentation.diff: Use trace_printk.
* earliest_deadline_first/main.c: Use ftrace.
* earliest_deadline_first/execution_trace-to-execution_trace_processed.sh:
Enable parsing ftrace result.
  • Loading branch information...
1 parent 68817fc commit 8cd2445f3a57b0602e5737e567ac5d74123850a8 @eus committed Jun 22, 2011
Showing with 285,829 additions and 114 deletions.
  1. +5 −0 earliest_deadline_first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem/conclusion.txt
  2. +84,432 −0 ..._deadline_first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem/result_001/execution_trace.txt
  3. BIN ...first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem/result_001/execution_trace_processed.ods
  4. BIN ...iest_deadline_first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem/result_001/tau_1_stats.bin
  5. BIN ...iest_deadline_first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem/result_001/tau_2_stats.bin
  6. BIN ...iest_deadline_first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem/result_001/tau_3_stats.bin
  7. +81,130 −0 ..._deadline_first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem/result_002/execution_trace.txt
  8. BIN ...first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem/result_002/execution_trace_processed.ods
  9. BIN ...iest_deadline_first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem/result_002/tau_1_stats.bin
  10. BIN ...iest_deadline_first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem/result_002/tau_2_stats.bin
  11. BIN ...iest_deadline_first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem/result_002/tau_3_stats.bin
  12. +119,918 −0 ..._deadline_first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem/result_003/execution_trace.txt
  13. BIN ...first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem/result_003/execution_trace_processed.ods
  14. BIN ...iest_deadline_first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem/result_003/tau_1_stats.bin
  15. BIN ...iest_deadline_first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem/result_003/tau_2_stats.bin
  16. BIN ...iest_deadline_first/006-HRTICK_enabled-bogus_outdated_rq_clock_problem/result_003/tau_3_stats.bin
  17. +74 −0 earliest_deadline_first/006-detect_potential_outdated_rq_clock.sh
  18. +47 −8 earliest_deadline_first/README
  19. +4 −4 earliest_deadline_first/execution_trace-to-execution_trace_processed.sh
  20. +27 −2 earliest_deadline_first/main.c
  21. +38 −0 earliest_deadline_first/process_experiment_result.sh
  22. +58 −0 earliest_deadline_first/run_experiment.sh
  23. +96 −100 earliest_deadline_first/sched_dl_instrumentation.diff
@@ -0,0 +1,5 @@
+This experiment concludes that it is possible that the problem
+of outdated rq->clock observed in
+004-HRTICK_enabled-various_problems-outdated_rq_clock was caused by
+the use of printk because using trace_printk, the problem is no longer
+observed in this experiment.
Oops, something went wrong.
Oops, something went wrong.
Oops, something went wrong.
@@ -0,0 +1,74 @@
+#!/bin/bash
+
+if [ $# -ne 1 ]; then
+ echo "Usage: $0 SCHED_DEADLINE_TIMELINE_CSV_FILE"
+ exit 1
+fi
+
+SCHED_DL_TIMELINE=$1
+
+# More keyword should be appended using '\\|' like 'x\\|y'
+UNDESIRED_KEYWORD='select_task_rq_dl'
+
+# The algorithm to detect potential outdated rq->clock for each
+# timeline differs only in the number of \t character to be detected
+# because the \t character signifies whose timeline is which. The
+# first sed looks only for "resumes its BW pair" in the timeline that
+# belongs to a particular task. If the token falls in another task's
+# timeline, the token and its group is removed in one go: sed -n -e
+# '{N;s%^[0-9.]\+\t[0-9]\+\t\t\(\t\)\?[^\t]\+%%;t;p}'
+
+# Since an outdated rq->clock is only apparent when the task resuming
+# the BW is not run after the decision to resume the BW, the first sed
+# s command removes any candidate that runs itself after deciding to
+# resume the BW: s%^[0-9.]\+\t[0-9]\+\t[^\t]\+%%
+
+# Since an outdated rq->clock is most apparent when the task resuming
+# the BW is delayed by another task running quite long, the second sed
+# s command removes any candidate whose intervening task does not run
+# long enough:
+# s%^[0-9.]\+\t[0-9]\+\t\t\(\t\)\?\('$UNDESIRED_KEYWORD'\)%%
+
+# The remaining candidates should then be inspected manually to decide
+# whether the budget, which the task resuming the BW had when the task
+# decided to resume its BW, can still be used fully after the
+# intervening task picks the task that resumes the BW.
+
+# Detect the timeline of Task 1
+grep -A 1 resumes $SCHED_DL_TIMELINE \
+ | grep -v ^-- \
+ | sed -n -e '{N;s%^[0-9.]\+\t[0-9]\+\t\t\(\t\)\?[^\t]\+%%;t;p}' \
+ | sed -n \
+ -e '1~2 h' \
+ -e '0~2 {
+s%^[0-9.]\+\t[0-9]\+\t[^\t]\+%%;
+t;
+s%^[0-9.]\+\t[0-9]\+\t\t\(\t\)\?\('$UNDESIRED_KEYWORD'\)%%;
+t;
+H;g;p}'
+
+# Detect the timeline of Task 2
+grep -A 1 resumes $SCHED_DL_TIMELINE \
+ | grep -v ^-- \
+ | sed -n -e '{N;s%^[0-9.]\+\t[0-9]\+\t\(\t\t\)\?[^\t]\+%%;t;p}' \
+ | sed -n \
+ -e '1~2 h' \
+ -e '0~2 {
+s%^[0-9.]\+\t[0-9]\+\t\t[^\t]\+%%;
+t;
+s%^[0-9.]\+\t[0-9]\+\t\(\t\t\)\?\('$UNDESIRED_KEYWORD'\)%%;
+t;
+H;g;p}'
+
+# Detect the timeline of Task 3
+grep -A 1 resumes $SCHED_DL_TIMELINE\
+ | grep -v ^-- \
+ | sed -n -e '{N;s%^[0-9.]\+\t[0-9]\+\t\(\t\)\?[^\t]\+%%;t;p}' \
+ | sed -n \
+ -e '1~2 h' \
+ -e '0~2 {
+s%^[0-9.]\+\t[0-9]\+\t\t\t[^\t]\+%%;
+t;
+s%^[0-9.]\+\t[0-9]\+\t\(\t\)\?\('$UNDESIRED_KEYWORD'\)%%;
+t;
+H;g;p}'
@@ -50,13 +50,20 @@ SCHED_DEADLINE works. This is done by instrumenting SCHED_DEADLINE
scheduling logic at commit f2ebcfd122cdab46f1e9eabe91e1549285b5a00b by
applying sched_dl_instrumentation.diff.
-The resulting printk messages can be extracted with a command like
-'dmesg | grep' to a file. The file can then be processed using
-execution_trace-to-execution_trace_processed.sh to get a .csv
-file. The .csv file can then be processed further using a spreadsheet
-program to obtain an execution timeline. An example is the file
-execution_trace_processed.ods in directory
-001-what_is_wrong_with_commit_fd2579d11c6e49add3803ea5657c1c02c7e4fde9.
+In the above context, this experiment unit should be run by executing
+./run_experiment.sh that requires the kernel to have ftrace enabled in
+the debugfs. The result of running the executable will be
+/tmp/sched_dl_timeline.csv. The .csv file can then be processed
+further using a spreadsheet program to obtain an execution
+timeline. An example is the file execution_trace_processed.ods in
+directory
+006-HRTICK_enabled-bogus_outdated_rq_clock_problem/result_003. Aside
+from the .csv file, the executable will also produce
+./execution_trace.txt containing the ftrace result. To obtain the .csv
+file from this ftrace result, use the executable
+process_experiment_result.sh that will internally use
+execution_trace-to-execution_trace_processed.sh to produce the .csv
+file.
Some messages in the execution timeline have the following associated
meanings:
@@ -108,7 +115,9 @@ problems observed in SCHED_DEADLINE scheduling logic. This is produced
by making Tadeus's GNU/Linux Ubuntu 10.10 machine try to establish a
wireless LAN connection. This was done by selecting an access point in
GNOME wireless applet. The problems can be fixed by applying
-004-HRTICK_enabled-various_problems-solution.diff to
+004-HRTICK_enabled-various_problems-fail_to_enforce_bandwidth.diff,
+004-HRTICK_enabled-various_problems-outdated_rq_clock.diff, and
+004-HRTICK_enabled-various_problems-partial_solution.diff to
SCHED_DEADLINE. The directory 004-HRTICK_enabled-various_problems-*
highlights the problems to be fixed as well as the fixing results.
@@ -118,3 +127,33 @@ the fixes introduced at the previous experiment. This is produced by
making Tadeus's GNU/Linux Ubuntu 10.10 machine try to establish a
wireless LAN connection. This was done by selecting an access point in
GNOME wireless applet.
+
+The directory 006-HRTICK_enabled-bogus_outdated_rq_clock_problem
+contains the result that refutes the previous observation that
+SCHED_DEADLINE at commit f2ebcfd122cdab46f1e9eabe91e1549285b5a00b
+requires the patch
+004-HRTICK_enabled-various_problems-outdated_rq_clock.diff. Specifically,
+Dario Faggioli pointed out in a private e-mail that it is better to
+leave the time accounting to Linux generic scheduler just like what
+SCHED_FAIR and SCHED_RT do. An inspection of the Linux sched.c reveals
+that rq->clock is updated in function dequeue_task and, if a task is
+not dequeued in function schedule, rq->clock is updated in function
+put_prev_task. That is, the problem described in
+004-HRTICK_enabled-various_problems-outdated_rq_clock should have
+never been observed and so there is no need to apply patch
+004-HRTICK_enabled-various_problems-outdated_rq_clock.diff. To Tadeus,
+it seems that the use of printk interferes with the mechanism to
+update the rq->clock. Therefore, as Dario Faggioli suggested, the
+printk is replaced by trace_printk and the experiment result is
+obtained by applying sched_dl_instrumentation.diff and running
+./run_experiment.sh while making Tadeus's GNU/Linux Ubuntu 10.10
+machine try to establish a wireless LAN connection. This was done by
+selecting an access point in GNOME wireless applet. The file
+./006-detect_potential_outdated_rq_clock.sh is used to help
+distinguish the result that most likely show the problem of outdated
+rq->clock as in:
+./run_experiment.sh \
+ && ./006-detect_potential_outdated_rq_clock.sh /tmp/sched_dl_timeline.csv
+If there is no output, the whole command is simply repeated
+again. Otherwise, /tmp/sched_dl_timeline.csv is manually processed
+using a spreadsheet program.
@@ -17,10 +17,10 @@ for ((i = 1; i <= 3; i++)); do
shift
done
-sed -e 's%^\[[^0-9]*\([^]]\+\)\] \['"$TASK_1_PID"'\] \(.*\)%\1'\\t'\2%' \
- -e 's%^\[[^0-9]*\([^]]\+\)\] \['"$TASK_2_PID"'\] \(.*\)%\1'\\t\\t'\2%' \
- -e 's%^\[[^0-9]*\([^]]\+\)\] \['"$TASK_3_PID"'\] \(.*\)%\1'\\t\\t\\t'\2%' \
+sed -e 's%^\([^[]\+\)\[[^0-9]*\([^]]\+\)\] \['"$TASK_1_PID"'\] \(.*\)%\1\2'\\t'\3%' \
+ -e 's%^\([^[]\+\)\[[^0-9]*\([^]]\+\)\] \['"$TASK_2_PID"'\] \(.*\)%\1\2'\\t\\t'\3%' \
+ -e 's%^\([^[]\+\)\[[^0-9]*\([^]]\+\)\] \['"$TASK_3_PID"'\] \(.*\)%\1\2'\\t\\t\\t'\3%' \
-e 's% main ('"$TASK_1_PID"')% Task 1%' \
-e 's% main ('"$TASK_2_PID"')% Task 2%' \
-e 's% main ('"$TASK_3_PID"')% Task 3%' \
- "$EXECUTION_TRACE_FILE"
+ "$EXECUTION_TRACE_FILE"
@@ -47,8 +47,8 @@ MAIN_BEGIN("earliest_deadline_first", "stderr", NULL)
relative_time *busyloop_tolerance = to_utility_time_dyn(100, us);
unsigned busyloop_search_passes = 10;
- relative_time *offset_to_start = to_utility_time_dyn(3, s);
- relative_time *offset_to_stop = to_utility_time_dyn(3205, ms);
+ relative_time *offset_to_start = to_utility_time_dyn(2, s);
+ relative_time *offset_to_stop = to_utility_time_dyn(2405, ms);
/* END: Tuneable parameters */
#define set_manual_gc(id) \
@@ -76,6 +76,8 @@ MAIN_BEGIN("earliest_deadline_first", "stderr", NULL)
task *tau_2 = NULL;
task *tau_3 = NULL;
char t_str[32];
+ const char *ktrace_path = "/sys/kernel/debug/tracing/tracing_enabled";
+ FILE *ktrace_file = NULL;
/* Determining overheads */
if (job_statistics_overhead(0, &job_stats_overhead) != 0) {
@@ -250,10 +252,27 @@ MAIN_BEGIN("earliest_deadline_first", "stderr", NULL)
} \
} while (0)
+ ktrace_file = utility_file_open_for_writing(ktrace_path);
+ if (ktrace_file == NULL) {
+ log_error("Cannot open ktrace file");
+ goto error;
+ }
+ errno = 0;
+ if (setvbuf(ktrace_file, NULL, _IONBF, 0) != 0) {
+ if (errno) {
+ log_syserror("Cannot unbuffer ktrace_file");
+ } else {
+ log_error("Cannot unbuffer ktrace_file");
+ }
+ goto error;
+ }
+
create_task_thread(1);
create_task_thread(2);
create_task_thread(3);
+ fprintf(ktrace_file, "1");
+
#undef create_task_thread
/* END: Create task threads */
@@ -286,6 +305,8 @@ MAIN_BEGIN("earliest_deadline_first", "stderr", NULL)
#undef join_thread
/* END: Join task threads */
+ fprintf(ktrace_file, "0");
+
/* Check task return statuses */
#define check_rc(id) do { \
if (tau_ ## id ## _thread_args.rc != 0) { \
@@ -307,6 +328,10 @@ MAIN_BEGIN("earliest_deadline_first", "stderr", NULL)
error:
/* Clean-up */
+ if (ktrace_file != NULL) {
+ utility_file_close(ktrace_file, ktrace_path);
+ }
+
if (tau_3 != NULL) {
task_destroy(tau_3);
}
@@ -0,0 +1,38 @@
+#!/bin/bash
+
+if [ $# -ne 1 ]; then
+ echo "Usage: $0 KERNEL_TRACE_FILE"
+ exit 1
+fi
+
+SCHED_DL_DATA=/tmp/sched_dl_data.txt
+SCHED_DL_MSG='@[0-9]\+'
+SCHED_DL_TIMELINE=/tmp/sched_dl_timeline.csv
+
+## Extract the SCHED_DEADLINE trace_printk messages
+grep $SCHED_DL_MSG $1 \
+ | sed -e 's%.* \([.0-9]\+\):[^@]\+@\([^ ]\+\) \(.*\)%\1\t[\2] \3%' \
+ > $SCHED_DL_DATA
+
+## Extract the PIDs of the tasks
+task_pids=`sed -e 's%.*\[[^]]\+\] \[\([^]]\+\)\].*%\1%' $SCHED_DL_DATA \
+ | sort -u`
+task_1_pid=`echo "$task_pids" | sed -n -e '1 p'`
+task_2_pid=`echo "$task_pids" | sed -n -e '2 p'`
+task_3_pid=`echo "$task_pids" | sed -n -e '3 p'`
+if [ x"$task_1_pid"y == xy \
+ -o x"$task_2_pid"y == xy \
+ -o x"$task_3_pid"y == xy \
+ -o x`echo "$task_pids" | sed -n -e '4 p'`y != xy ]; then
+ echo "Cannot find exactly three PIDs; try to enlarge tracing buffer" >&2
+ exit 1
+fi
+if [ $((task_1_pid + 1)) -ne $task_2_pid \
+ -o $((task_2_pid + 1)) -ne $task_3_pid ]; then
+ echo "The three PIDs are not consecutive; try to enlarge tracing buffer" >&2
+ exit 1
+fi
+
+## Generate the timeline table
+./execution_trace-to-execution_trace_processed.sh $SCHED_DL_DATA \
+ $task_1_pid $task_2_pid $task_3_pid > $SCHED_DL_TIMELINE
@@ -0,0 +1,58 @@
+#!/bin/bash
+
+RAW_DATA=./execution_trace.txt
+
+SCHED_DL_MSG='@[0-9]\+'
+
+BUFSIZE=14080
+KTRACE_DIR=/sys/kernel/debug/tracing
+KTRACE_TRACING_ENABLED=$KTRACE_DIR/tracing_enabled
+KTRACE_TRACING_CPUMASK=$KTRACE_DIR/tracing_cpumask
+KTRACE_TRACING_BUFFER_SIZE_KB=$KTRACE_DIR/buffer_size_kb
+KTRACE_CURRENT_TRACER=$KTRACE_DIR/current_tracer
+KTRACE_TRACE=$KTRACE_DIR/trace
+SCHED_FEATURES=/sys/kernel/debug/sched_features
+
+# $1 what to write
+# $2 the file to write to
+function kwrite {
+ echo $1 | sudo tee $2
+}
+
+# $1 the file used to disable a single feature
+function kwrite_disable {
+ kwrite 0 $1
+}
+
+# $1 the feature name
+# $2 the file used to disable a collection of features
+function kwrite_disable_feat {
+ kwrite NO_$1 $2
+}
+
+# $1 the feature name
+# $2 the file used to enable a collection of features
+function kwrite_enable_feat {
+ kwrite $1 $2
+}
+
+set -e
+
+# Preparing the tracer
+kwrite_disable $KTRACE_TRACING_ENABLED
+kwrite 01 $KTRACE_TRACING_CPUMASK
+kwrite $BUFSIZE $KTRACE_TRACING_BUFFER_SIZE_KB
+kwrite function $KTRACE_CURRENT_TRACER
+
+# Do the experiment
+kwrite_enable_feat HRTICK $SCHED_FEATURES
+sudo ./main
+kwrite_disable_feat HRTICK $SCHED_FEATURES
+
+# Processing the experiment result
+## Take only the relevant part
+starting_line=`grep -m 1 -n $SCHED_DL_MSG $KTRACE_TRACE | cut -d: -f 1`
+tail -n +$starting_line $KTRACE_TRACE > $RAW_DATA
+
+## Process it
+./process_experiment_result.sh $RAW_DATA
Oops, something went wrong.

0 comments on commit 8cd2445

Please sign in to comment.