Add new fields in the per-task profiling info structure

- push_{start,end}_time indicates when the scheduler calls the push method
- pop_{start,end}_time indicates when the scheduler calls the pop method
- acquire_data_{start,end}_time indicates that the DSM is fetching the data
- release_data_{start,end}_time indicates that the DSM is releasing the data
- callback_{start,end}_time indicates when the callback has been executed

include/starpu_profiling.h

@@ -40,9 +40,31 @@ extern "C" {
 #define STARPU_PROFILING_ENABLE		1
 
 struct starpu_task_profiling_info {
+	/* Task submission */
 	struct timespec submit_time;
+
+	/* Scheduling overhead */
+	struct timespec push_start_time;
+	struct timespec push_end_time;
+	struct timespec pop_start_time;
+	struct timespec pop_end_time;
+
+	/* Take input data */
+	struct timespec acquire_data_start_time;
+	struct timespec acquire_data_end_time;
+
+	/* Execution */
 	struct timespec start_time;
 	struct timespec end_time;
+
+	/* Release data */
+	struct timespec release_data_start_time;
+	struct timespec release_data_end_time;
+
+	/* Callback */
+	struct timespec callback_start_time;
+	struct timespec callback_end_time;
+
 	/* TODO add expected length, expected start/end ? */
 	int workerid;
 };

src/core/jobs.c

@@ -21,6 +21,7 @@
 #include <core/dependencies/data_concurrency.h>
 #include <common/config.h>
 #include <common/utils.h>
+#include <profiling/profiling.h>
 #include <profiling/bound.h>
 
 size_t _starpu_job_get_data_size(starpu_job_t j)
@@ -147,10 +148,15 @@ void _starpu_handle_job_termination(starpu_job_t j, unsigned job_is_already_lock
  	 * of the task itself */
 	if (task->callback_func)
 	{
+		int profiling = starpu_profiling_status_get();
+		if (profiling && task->profiling_info)
+			starpu_clock_gettime(&task->profiling_info->callback_start_time);
+
 		/* so that we can check whether we are doing blocking calls
 		 * within the callback */
 		_starpu_set_local_worker_status(STATUS_CALLBACK);
 		
+		
 		/* Perhaps we have nested callbacks (eg. with chains of empty
 		 * tasks). So we store the current task and we will restore it
 		 * later. */
@@ -165,6 +171,9 @@ void _starpu_handle_job_termination(starpu_job_t j, unsigned job_is_already_lock
 		_starpu_set_current_task(current_task);
 
 		_starpu_set_local_worker_status(STATUS_UNKNOWN);
+
+		if (profiling && task->profiling_info)
+			starpu_clock_gettime(&task->profiling_info->callback_end_time);
 	}
 
 	_starpu_sched_post_exec_hook(task);

src/core/sched_policy.c

@@ -20,6 +20,7 @@
 #include <common/config.h>
 #include <common/utils.h>
 #include <core/sched_policy.h>
+#include <profiling/profiling.h>
 
 static struct starpu_sched_policy_s policy;
 
@@ -206,6 +207,7 @@ int _starpu_push_task(starpu_job_t j, unsigned job_is_already_locked)
         _STARPU_LOG_IN();
 
 	task->status = STARPU_TASK_READY;
+	_starpu_profiling_set_task_push_start_time(task);
 
 	/* in case there is no codelet associated to the task (that's a control
 	 * task), we directly execute its callback and enforce the
@@ -236,19 +238,52 @@ int _starpu_push_task(starpu_job_t j, unsigned job_is_already_locked)
 
 		ret = policy.push_task(task);
 	}
+
+	_starpu_profiling_set_task_push_end_time(task);
+
         _STARPU_LOG_OUT();
         return ret;
 }
 
 struct starpu_task *_starpu_pop_task(void)
 {
-	return policy.pop_task();
+	struct starpu_task *task;
+
+	/* We can't tell in advance which task will be picked up, so we measure
+	 * a timestamp, and will attribute it afterwards to the task. */
+	int profiling = starpu_profiling_status_get();
+	struct timespec pop_start_time;
+	if (profiling)
+		starpu_clock_gettime(&pop_start_time);
+
+	task = policy.pop_task();
+
+	/* Note that we may get a NULL task in case the scheduler was unlocked
+	 * for some reason. */
+	if (profiling && task)
+	{
+		struct starpu_task_profiling_info *profiling_info;
+		profiling_info = task->profiling_info;
+
+		/* The task may have been created before profiling was enabled,
+		 * so we check if the profiling_info structure is available
+		 * even though we already tested if profiling is enabled. */
+		if (profiling_info)
+		{
+			memcpy(&profiling_info->pop_start_time,
+				&pop_start_time, sizeof(struct timespec));
+			starpu_clock_gettime(&profiling_info->pop_end_time);
+		}
+	}
+
+	return task;
 }
 
 struct starpu_task *_starpu_pop_every_task(void)
 {
 	STARPU_ASSERT(policy.pop_every_task);
 
+	/* TODO set profiling info */
 	return policy.pop_every_task();
 }
 

src/datawizard/coherency.c

@@ -19,6 +19,7 @@
 #include <datawizard/copy_driver.h>
 #include <datawizard/write_back.h>
 #include <core/dependencies/data_concurrency.h>
+#include <profiling/profiling.h>
 
 uint32_t _starpu_select_node_to_handle_request(uint32_t src_node, uint32_t dst_node) 
 {
@@ -414,6 +415,10 @@ int _starpu_fetch_task_input(struct starpu_task *task, uint32_t mask)
 {
 	STARPU_TRACE_START_FETCH_INPUT(NULL);
 
+	int profiling = starpu_profiling_status_get();
+	if (profiling && task->profiling_info)
+		starpu_clock_gettime(&task->profiling_info->acquire_data_start_time);
+
 	starpu_buffer_descr *descrs = task->buffers;
 	unsigned nbuffers = task->cl->nbuffers;
 
@@ -453,6 +458,9 @@ int _starpu_fetch_task_input(struct starpu_task *task, uint32_t mask)
 		}
 	}
 
+	if (profiling && task->profiling_info)
+		starpu_clock_gettime(&task->profiling_info->acquire_data_end_time);
+
 	STARPU_TRACE_END_FETCH_INPUT(NULL);
 
 	return 0;
@@ -470,6 +478,10 @@ void _starpu_push_task_output(struct starpu_task *task, uint32_t mask)
 {
 	STARPU_TRACE_START_PUSH_OUTPUT(NULL);
 
+	int profiling = starpu_profiling_status_get();
+	if (profiling && task->profiling_info)
+		starpu_clock_gettime(&task->profiling_info->release_data_start_time);
+
         starpu_buffer_descr *descrs = task->buffers;
         unsigned nbuffers = task->cl->nbuffers;
 
@@ -503,6 +515,9 @@ void _starpu_push_task_output(struct starpu_task *task, uint32_t mask)
 			_starpu_release_data_enforce_sequential_consistency(task, handle);
 	}
 
+	if (profiling && task->profiling_info)
+		starpu_clock_gettime(&task->profiling_info->release_data_end_time);
+
 	STARPU_TRACE_END_PUSH_OUTPUT(NULL);
 }
 

src/profiling/profiling.c

@@ -118,10 +118,6 @@ struct starpu_task_profiling_info *_starpu_allocate_profiling_info_if_needed(voi
 	{
 		info = calloc(1, sizeof(struct starpu_task_profiling_info));
 		STARPU_ASSERT(info);
-
-		starpu_timespec_clear(&info->submit_time);
-		starpu_timespec_clear(&info->start_time);
-		starpu_timespec_clear(&info->end_time);
 	}
 
 	return info;
@@ -282,6 +278,31 @@ int starpu_worker_get_profiling_info(int workerid, struct starpu_worker_profilin
 	return 0;
 }
 
+/* When did the task reach the scheduler  ? */
+void _starpu_profiling_set_task_push_start_time(struct starpu_task *task)
+{
+	if (!profiling)
+		return;
+
+	struct starpu_task_profiling_info *profiling_info;
+	profiling_info = task->profiling_info;
+
+	if (profiling_info)
+		starpu_clock_gettime(&profiling_info->push_start_time);
+}
+
+void _starpu_profiling_set_task_push_end_time(struct starpu_task *task)
+{
+	if (!profiling)
+		return;
+
+	struct starpu_task_profiling_info *profiling_info;
+	profiling_info = task->profiling_info;
+
+	if (profiling_info)
+		starpu_clock_gettime(&profiling_info->push_end_time);
+}
+
 /*
  *	Bus profiling
  */

src/profiling/profiling.h

@@ -61,4 +61,7 @@ int _starpu_register_bus(int src_node, int dst_node);
  * memory nodes. */
 void _starpu_bus_update_profiling_info(int src_node, int dst_node, size_t size);
 
+void _starpu_profiling_set_task_push_start_time(struct starpu_task *task);
+void _starpu_profiling_set_task_push_end_time(struct starpu_task *task);
+
 #endif // __PROFILING_H__