[PATCH] measure execution time of each step in shell scripts

Denys Vlasenko vda.linux at googlemail.com
Thu Oct 8 17:14:04 UTC 2015


On Tue, Sep 22, 2015 at 6:19 PM, Petra Mazdin <petra.mazdin1 at gmail.com> wrote:
> So, the idea is to take start and end time separately for each executed
> step. In order to avoid wrong interpretation between different commands,
> each time pid (process ID), start/end time and exact command are taken so
> that it was possible to analyze them by the same pid and calculate duration.
>
> All data are then saved in a list whose elements differ by its type: start
> pid (long int), end pid (long int), start time (long int), end time (long
> int) and command (char *).

You don't need a separate list. Add a new member to struct procstat
and store there its start time when new process is created. Say,

ps->ps_start_time_ns = monotonic_ns();


> A part of busybox ash where start time should be taken is right before
> dowait() where parent process starts to wait for forked child process to
> finish its execution (all in waitforjob()). When ps->ps_status becomes -1,
> meaning that a child is finished, exact time stamp is taken as end time.
>
> Also, we need a special treatment for pipelined processes, meaning that it
> can happen that  there exist some processes executing in parallel. What
> happens is that final time stamps that are proceeded to further analysis are
> the ones taken at the moment the last part of a pipeline is executed. That
> is, of course, wrong because parts are executed in parallel and any on them
> can finish earlier.

I would not complicate my mental view of this task with
even bothering to remember that there are pipelines.

You can simply track death of every process separately, here:

        pid = waitpid(-1, &status, wait_flags);
        if (pid <= 0)
                return pid;
        thisjob = NULL;
        for (jp = curjob; jp; jp = jp->prev_job) {
                       if (ps->ps_pid == pid) {
                                TRACE(("Job %d: changing status of proc %d "
                                        "from 0x%x to 0x%x\n",
                                        jobno(jp), pid, ps->ps_status, status));
                                ps->ps_status = status;
                                thisjob = jp;
+if (!WIFSTOPPED(status) && I_want_to_track_process_times) {
+        /* process ps died */
+        long long int elapsed_time = monotonic_ns() - ps->ps_start_time_ns;
+        open_log_file_append_and_close(ps->ps_cmd, elapsed_time);
+}
                        }

No additional new lists are necessary.

If you replace waitpid() with wait4() above, you can display more information,
such as how much CPU time dead process actually used:
if process ran for 10 seconds, it could have slept it all, or it could use CPU
for 6 seconds, and wait for something the remaining 4 seconds.
You may want to know these details.


More information about the busybox mailing list