Also show scheduling cost at push time

src/common/fxt.h

@@ -107,8 +107,6 @@
 
 #define _STARPU_FUT_EVENT	0x513c
 
-#define _STARPU_FUT_WORKER_SCHEDULING_START	0x513e
-
 #define _STARPU_FUT_LOCKING_MUTEX	0x5140	
 #define _STARPU_FUT_MUTEX_LOCKED	0x5141	
 
@@ -156,6 +154,11 @@
 #define _STARPU_FUT_BARRIER_WAIT_BEGIN		0x5162
 #define _STARPU_FUT_BARRIER_WAIT_END		0x5163
 
+#define _STARPU_FUT_WORKER_SCHEDULING_START	0x5164
+#define _STARPU_FUT_WORKER_SCHEDULING_END	0x5165
+#define _STARPU_FUT_WORKER_SCHEDULING_PUSH	0x5166
+#define _STARPU_FUT_WORKER_SCHEDULING_POP	0x5167
+
 #ifdef STARPU_USE_FXT
 #include <fxt/fxt.h>
 #include <fxt/fut.h>
@@ -487,6 +490,15 @@ do {										\
 #define _STARPU_TRACE_WORKER_SCHEDULING_START	\
 	FUT_DO_PROBE1(_STARPU_FUT_WORKER_SCHEDULING_START, _starpu_gettid());
 
+#define _STARPU_TRACE_WORKER_SCHEDULING_END	\
+	FUT_DO_PROBE1(_STARPU_FUT_WORKER_SCHEDULING_END, _starpu_gettid());
+
+#define _STARPU_TRACE_WORKER_SCHEDULING_PUSH	\
+	FUT_DO_PROBE1(_STARPU_FUT_WORKER_SCHEDULING_PUSH, _starpu_gettid());
+
+#define _STARPU_TRACE_WORKER_SCHEDULING_POP	\
+	FUT_DO_PROBE1(_STARPU_FUT_WORKER_SCHEDULING_POP, _starpu_gettid());
+
 #define _STARPU_TRACE_WORKER_SLEEP_START	\
 	FUT_DO_PROBE1(_STARPU_FUT_WORKER_SLEEP_START, _starpu_gettid());
 
@@ -760,6 +772,9 @@ do {										\
 #define _STARPU_TRACE_WORKER_DEINIT_START	do {} while(0)
 #define _STARPU_TRACE_WORKER_DEINIT_END(a)	do {} while(0)
 #define _STARPU_TRACE_WORKER_SCHEDULING_START		do {} while(0)
+#define _STARPU_TRACE_WORKER_SCHEDULING_END		do {} while(0)
+#define _STARPU_TRACE_WORKER_SCHEDULING_PUSH		do {} while(0)
+#define _STARPU_TRACE_WORKER_SCHEDULING_POP		do {} while(0)
 #define _STARPU_TRACE_WORKER_SLEEP_START		do {} while(0)
 #define _STARPU_TRACE_WORKER_SLEEP_END		do {} while(0)
 #define _STARPU_TRACE_USER_DEFINED_START		do {} while(0)

src/core/sched_policy.c

@@ -455,7 +455,14 @@ int _starpu_push_task_to_workers(struct starpu_task *task)
 			starpu_pthread_rwlock_t *changing_ctx_mutex = _starpu_sched_ctx_get_changing_ctx_mutex(sched_ctx->id);
 			STARPU_PTHREAD_RWLOCK_RDLOCK(changing_ctx_mutex);
 			nworkers = starpu_sched_ctx_get_nworkers(sched_ctx->id);
-			ret = nworkers == 0 ? -1 : sched_ctx->sched_policy->push_task(task);
+			if (nworkers == 0)
+				ret = -1;
+			else
+			{
+				_STARPU_TRACE_WORKER_SCHEDULING_PUSH
+				ret = sched_ctx->sched_policy->push_task(task);
+				_STARPU_TRACE_WORKER_SCHEDULING_POP
+			}
 			STARPU_PTHREAD_RWLOCK_UNLOCK(changing_ctx_mutex);
 		}
 

src/debug/traces/starpu_fxt.c

@@ -275,6 +275,28 @@ static void worker_set_state(double time, const char *prefix, long unsigned int
 #endif
 }
 
+static void worker_push_state(double time, const char *prefix, long unsigned int workerid, const char *name)
+{
+#ifdef STARPU_HAVE_POTI
+	char container[STARPU_POTI_STR_LEN];
+	thread_container_alias(container, STARPU_POTI_STR_LEN, prefix, workerid);
+	poti_PushState(time, container, "S", name);
+#else
+	fprintf(out_paje_file, "11	%.9f	%st%lu	S	%s\n", time, prefix, workerid, name);
+#endif
+}
+
+static void worker_pop_state(double time, const char *prefix, long unsigned int workerid)
+{
+#ifdef STARPU_HAVE_POTI
+	char container[STARPU_POTI_STR_LEN];
+	thread_container_alias(container, STARPU_POTI_STR_LEN, prefix, workerid);
+	poti_PopState(time, container, "S");
+#else
+	fprintf(out_paje_file, "12	%.9f	%st%lu	S\n", time, prefix, workerid);
+#endif
+}
+
 static void mpicommthread_set_state(double time, const char *prefix, const char *name)
 {
 #ifdef STARPU_HAVE_POTI
@@ -790,6 +812,36 @@ static void handle_start_scheduling(struct fxt_ev_64 *ev, struct starpu_fxt_opti
 		worker_set_state(get_event_time_stamp(ev, options), options->file_prefix, ev->param[0], "Sc");
 }
 
+static void handle_end_scheduling(struct fxt_ev_64 *ev, struct starpu_fxt_options *options)
+{
+	int worker;
+	worker = find_worker_id(ev->param[0]);
+	if (worker < 0) return;
+
+	if (out_paje_file)
+		worker_set_state(get_event_time_stamp(ev, options), options->file_prefix, ev->param[0], "B");
+}
+
+static void handle_push_scheduling(struct fxt_ev_64 *ev, struct starpu_fxt_options *options)
+{
+	int worker;
+	worker = find_worker_id(ev->param[0]);
+	if (worker < 0) return;
+
+	if (out_paje_file)
+		worker_push_state(get_event_time_stamp(ev, options), options->file_prefix, ev->param[0], "Sc");
+}
+
+static void handle_pop_scheduling(struct fxt_ev_64 *ev, struct starpu_fxt_options *options)
+{
+	int worker;
+	worker = find_worker_id(ev->param[0]);
+	if (worker < 0) return;
+
+	if (out_paje_file)
+		worker_pop_state(get_event_time_stamp(ev, options), options->file_prefix, ev->param[0]);
+}
+
 static void handle_start_sleep(struct fxt_ev_64 *ev, struct starpu_fxt_options *options)
 {
 	int worker;
@@ -1506,6 +1558,18 @@ void starpu_fxt_parse_new_file(char *filename_in, struct starpu_fxt_options *opt
 				handle_start_scheduling(&ev, options);
 				break;
 
+			case _STARPU_FUT_WORKER_SCHEDULING_END:
+				handle_end_scheduling(&ev, options);
+				break;
+
+			case _STARPU_FUT_WORKER_SCHEDULING_PUSH:
+				handle_push_scheduling(&ev, options);
+				break;
+
+			case _STARPU_FUT_WORKER_SCHEDULING_POP:
+				handle_pop_scheduling(&ev, options);
+				break;
+
 			case _STARPU_FUT_WORKER_SLEEP_START:
 				handle_start_sleep(&ev, options);
 				break;

src/debug/traces/starpu_paje.c

@@ -87,14 +87,14 @@ void _starpu_fxt_write_paje_header(FILE *file)
 	fprintf(file, "%%EndEventDef\n");
 	fprintf(file, "%%EventDef	PajePushState	11\n");
 	fprintf(file, "%%	Time	date\n");
-	fprintf(file, "%%	Type	string\n");
 	fprintf(file, "%%	Container	string\n");
+	fprintf(file, "%%	Type	string\n");
 	fprintf(file, "%%	Value	string\n");
 	fprintf(file, "%%EndEventDef\n");
 	fprintf(file, "%%EventDef	PajePopState	12\n");
 	fprintf(file, "%%	Time	date\n");
-	fprintf(file, "%%	Type	string\n");
 	fprintf(file, "%%	Container	string\n");
+	fprintf(file, "%%	Type	string\n");
 	fprintf(file, "%%EndEventDef\n");
 	fprintf(file, "%%EventDef	PajeSetVariable	13\n");
 	fprintf(file, "%%	Time	date\n");

src/drivers/driver_common/driver_common.c

@@ -163,7 +163,15 @@ static void _starpu_worker_set_status_scheduling(int workerid)
 		_STARPU_TRACE_WORKER_SCHEDULING_START;
 		_starpu_worker_set_status(workerid, STATUS_SCHEDULING);
 	}
+}
 
+static void _starpu_worker_set_status_scheduling_done(int workerid)
+{
+	if (_starpu_worker_get_status(workerid) == STATUS_SCHEDULING)
+	{
+		_STARPU_TRACE_WORKER_SCHEDULING_END;
+		_starpu_worker_set_status(workerid, STATUS_UNKNOWN);
+	}
 }
 
 static void _starpu_worker_set_status_sleeping(int workerid)
@@ -298,6 +306,8 @@ struct starpu_task *_starpu_get_worker_task(struct _starpu_worker *args, int wor
 
 	STARPU_PTHREAD_MUTEX_UNLOCK(&args->sched_mutex);
 
+	_starpu_worker_set_status_scheduling_done(workerid);
+
 	_starpu_worker_set_status_wakeup(workerid);
 	args->spinning_backoff = BACKOFF_MIN;