Skip to content

Commit

Permalink
Bang on profiling more.
Browse files Browse the repository at this point in the history
  • Loading branch information
@rocky
rocky committed May 30, 2015
1 parent aa9bca5 commit 6d05a78
Show file tree
Hide file tree
Showing 4 changed files with 74 additions and 30 deletions.
1 change: 1 addition & 0 deletions filedef.h
View file
Expand Up @@ -32,6 +32,7 @@ struct file
const char *hname; /* Hashed filename */
const char *vpath; /* VPATH/vpath pathname */
gmk_floc floc; /* location in Makefile - for tracing */
uint64_t elapsed_time; /* Runtime in 100microsec to build target */
unsigned int nlines; /* Number of lines in file - for debugging. */

const char *description; /* Description of target taken from comment.
Expand Down
23 changes: 15 additions & 8 deletions profile.c
View file
@@ -1,5 +1,6 @@
/* Compile with:
gcc -g3 -I . -c -DSTANDALONE profile.c -o test-profile.o
make mock.o
gcc mock.o version.o alloc.o globals.o misc.o output.o enter_file.o hash.o strcache.o test-profile.o -o test-profile
*/
#include <stdio.h>
Expand All @@ -18,7 +19,7 @@ typedef struct profile_call {
} profile_call_t;

struct profile_entry {
time_t elapsed_time; /* Time update target; used in --profile */
uint64_t elapsed_time; /* rutime in milliseconds */
const char *name;
gmk_floc floc; /* location in Makefile - for tracing */
profile_call_t *calls; /* List of targets this target calls. */
Expand Down Expand Up @@ -122,9 +123,9 @@ static unsigned int next_fn_num = 1;
#endif

extern void
add_target(file_t *target, file_t *prev, time_t elapsed_time) {
add_target(file_t *target, file_t *prev) {
profile_entry_t *p = add_profile_entry(target);
p->elapsed_time = elapsed_time;
p->elapsed_time = target->elapsed_time;
if (prev) {
profile_entry_t *q = add_profile_entry(prev);
if (q) {
Expand Down Expand Up @@ -160,13 +161,17 @@ callgrind_profile_entry (const void *item)
{
const profile_entry_t *p = item;
profile_call_t *c;
fprintf(callgrind_fd, "fl=%s\n\n", p->floc.filenm);
if (p->floc.filenm) fprintf(callgrind_fd, "fl=%s\n\n", p->floc.filenm);
fprintf(callgrind_fd, "fn=%s\n", p->name);
fprintf(callgrind_fd, "%lu %lu\n", p->floc.lineno, p->elapsed_time);
fprintf(callgrind_fd, "%lu %lu\n", p->floc.lineno,
p->elapsed_time == 0 ? 1 : p->elapsed_time);
for (c = p->calls; c; c = c->p_next) {
fprintf(callgrind_fd, "cfi=%s\n", c->p_target->floc.filenm);
if (c->p_target->floc.filenm)
fprintf(callgrind_fd, "cfi=%s\n", c->p_target->floc.filenm);
fprintf(callgrind_fd, "cfn=%s\n", c->p_target->name);
fprintf(callgrind_fd, "calls=1 %lu\n", p->floc.lineno);
fprintf(callgrind_fd, "%lu %lu\n", p->floc.lineno,
c->p_target->elapsed_time == 0 ? 1 : c->p_target->elapsed_time);
}
fprintf(callgrind_fd, "\n");
}
Expand Down Expand Up @@ -203,13 +208,15 @@ int main(int argc, const char * const* argv) {
target2->floc.filenm = "Makefile";
target2->floc.lineno = 5;
target2->prev = target;
add_target(target2, NULL, 500);
target2->elapsed_time = 500;
add_target(target2, NULL);

target3 = enter_file("all-recursive");
target3->floc.filenm = "Makefile";
target3->floc.lineno = 5;
target3->prev = target2;
add_target(target3, target2, 1000);
target3->elapsed_time = 1000;
add_target(target3, target2);

close_callgrind();
}
Expand Down
2 changes: 1 addition & 1 deletion profile.h
View file
Expand Up @@ -2,5 +2,5 @@
#include "filedef.h"
extern bool init_callgrind(const char *creator, const char *const *argv,
const char *program_status);
extern void add_target(file_t *target, file_t *prev, time_t elapsed_time);
extern void add_target(file_t *target, file_t *prev);
extern void close_callgrind(void);
78 changes: 57 additions & 21 deletions remake.c
View file
Expand Up @@ -420,6 +420,33 @@ complain (struct file *file)
}
}

/* #define GETTIME(t) \ */
/* time_error ||= (0 == gettimeofday(&t, NULL))); \ */

static inline bool
GETTIME(struct timeval *t) {
return (0 != gettimeofday(t, NULL));
}

static uint64_t
TIME_IN_100MICRO(struct timeval *time) {
return ((time->tv_sec * (uint64_t)10000) +
(uint64_t) (time->tv_usec / 100));
}

static uint64_t
time_diff(struct timeval *start_time, struct timeval *finish_time) {
struct timeval diff_time;
diff_time.tv_sec = finish_time->tv_sec - start_time->tv_sec;
diff_time.tv_usec = finish_time->tv_usec;
if (diff_time.tv_usec < start_time->tv_usec) {
diff_time.tv_usec += 1000000;
diff_time.tv_sec--;
}
diff_time.tv_usec -= start_time->tv_usec;
return TIME_IN_100MICRO(&diff_time);
}

/* Consider a single 'struct file' and update it as appropriate.
Return 0 on success, or non-0 on failure. */

Expand All @@ -434,8 +461,12 @@ update_file_1 (struct file *file, unsigned int depth,
struct dep *d, *ad;
struct dep amake;
int running = 0;
time_t start_time = profile_flag ? time(NULL) : 0;
time_t finished_time;
struct timeval finish_time;
struct timeval start_time;
bool time_error = false;

if (profile_flag)
time_error = time_error || GETTIME(&start_time);

DBF (DB_VERBOSE, _("Considering target file '%s'.\n"));
p_stack_top = p_call_stack = trace_push_target(p_call_stack, file);
Expand Down Expand Up @@ -480,13 +511,10 @@ update_file_1 (struct file *file, unsigned int depth,
return 0;
case cs_finished:
DBF (DB_VERBOSE, _("Finished updating file '%s'.\n"));
if (profile_flag) {
finished_time = time(NULL);
if (start_time > 0 && finished_time > 0 &&
p_call_stack->p_parent) {
add_target(file, p_call_stack->p_parent->p_target,
finished_time - start_time);
}
if (profile_flag && !time_error && p_call_stack->p_parent) {
time_error = time_error || GETTIME(&finish_time);
file->elapsed_time = time_diff(&start_time, &finish_time);
add_target(file, p_call_stack->p_parent->p_target);
}
trace_pop_target(p_call_stack);
return file->update_status;
Expand Down Expand Up @@ -711,8 +739,13 @@ update_file_1 (struct file *file, unsigned int depth,

DBF (DB_VERBOSE, _("Finished prerequisites of target file '%s'.\n"));

time_error = time_error || GETTIME(&finish_time);
if (profile_flag && !time_error && p_call_stack->p_parent) {
file->elapsed_time = time_diff(&start_time, &finish_time);
}

if ( file->tracing & BRK_AFTER_PREREQ )
enter_debugger(p_call_stack, file, 0, DEBUG_BRKPT_AFTER_PREREQ);
enter_debugger(p_call_stack, file, 0, DEBUG_BRKPT_AFTER_PREREQ);

if (running)
{
Expand Down Expand Up @@ -855,6 +888,12 @@ update_file_1 (struct file *file, unsigned int depth,
VPATH filename if we found one. hfile will be either the
local name if no VPATH or the VPATH name if one was found. */

time_error = time_error || GETTIME(&finish_time);
if (file && profile_flag && !time_error && p_call_stack->p_parent) {
file->elapsed_time = time_diff(&start_time, &finish_time);
add_target(file, p_call_stack->p_parent->p_target);
}

while (file)
{
file->name = file->hname;
Expand Down Expand Up @@ -883,13 +922,10 @@ update_file_1 (struct file *file, unsigned int depth,
DBF (DB_VERBOSE, _("Recipe of '%s' is being run.\n"));
if ( file->tracing & BRK_AFTER_CMD || i_debugger_stepping )
enter_debugger(p_call_stack, file, 0, DEBUG_BRKPT_AFTER_CMD);
if (profile_flag) {
finished_time = time(NULL);
if (start_time > 0 && finished_time > 0 &&
p_call_stack->p_parent) {
add_target(file, p_call_stack->p_parent->p_target,
finished_time - start_time);
}
time_error = time_error || GETTIME(&finish_time);
if (profile_flag && !time_error && p_call_stack->p_parent) {
file->elapsed_time = time_diff(&start_time, &finish_time);
add_target(file, p_call_stack->p_parent->p_target);
}
trace_pop_target(p_call_stack);
return 0;
Expand All @@ -914,11 +950,11 @@ update_file_1 (struct file *file, unsigned int depth,
if ( file->tracing & BRK_AFTER_CMD || i_debugger_stepping )
enter_debugger(p_call_stack, file, 0, DEBUG_BRKPT_AFTER_CMD);
if (profile_flag) {
finished_time = time(NULL);
if (start_time > 0 && finished_time > 0 &&
time_error = time_error || GETTIME(&finish_time);
if (profile_flag && !time_error &&
p_call_stack->p_parent) {
add_target(file, p_call_stack->p_parent->p_target,
finished_time - start_time);
file->elapsed_time = time_diff(&start_time, &finish_time);
add_target(file, p_call_stack->p_parent->p_target);
}
}

Expand Down

0 comments on commit 6d05a78

Please sign in to comment.