Print status messages in parallel_emerge about jobs that are longer than 2 mins.

Print status messages in parallel_emerge about jobs that are longer than 2 mins.

Currently, if a build is slow, you only get debug output after an hour.
This is to allow for uncluttered output. If output is too cluttered, it's hard
to distinguish regular output from errors.

The problem with this approach is that it's often hard to debug why the build
is slow. Now that Chrome builds by default, it takes over an hour to build,
and people see little indication as to why. You can show the output with
build_packages --showoutput, but that is often too verbose and clutters the
output too much.

Here's an example log snippet that is hard to debug:

Pending 2, Ready 0, Running 1, Retrying 0, Total 22 [Time 5m20.5s Load 3.69 3.04 2.66]
Pending 2, Ready 0, Running 1, Retrying 0, Total 22 [Time 5m25.5s Load 3.40 2.99 2.65]
... yada yada yada ...
Pending 2, Ready 0, Running 1, Retrying 0, Total 22 [Time 45m32.9s Load 1.00 1.18 2.95]

From the above output, we see that a package is building for a long time, but
we don't know what package. We should output the package name every two minutes
at least so people know what package is taking so long. That's what this change
implements.

BUG=chromium-os:8575
TEST=Confirmed new status appear for regular build_packages. Confirmed
     build_packages --showoutput is unchanged.

Change-Id: Ie18b23ac7a8a6e2c24b43ec3691606c7da5e43cb

Committed: http://chrome-svn/viewvc/chromeos?view=rev&revision=0addea3

[kliegs, 2010-11-02 20:07:58]

I'd say print info for any job more than 10 minutes.  An hour is a long time
to wait But only print the job list every 5 minutes

Although I expect you'll find many people with their own opinion on the
right intervals :)

On Tue, Nov 2, 2010 at 4:04 PM, <davidjames@chromium.org> wrote:

> Reviewers: anush, Nick Sanders,
>
> Description:
> Print status messages in parallel_emerge about jobs that are longer than 2
> mins.
>
> Currently, if a build is slow, you only get debug output after an hour.
> This is to allow for uncluttered output. If output is too cluttered, it's
> hard
> to distinguish regular output from errors.
>
> The problem with this approach is that it's often hard to debug why the
> build
> is slow. Now that Chrome builds by default, it takes over an hour to build,
> and people see little indication as to why. You can show the output with
> build_packages --showoutput, but that is often too verbose and clutters the
> output too much.
>
> Here's an example log snippet that is hard to debug:
>
> Pending 2, Ready 0, Running 1, Retrying 0, Total 22 [Time 5m20.5s Load 3.69
> 3.04
> 2.66]
> Pending 2, Ready 0, Running 1, Retrying 0, Total 22 [Time 5m25.5s Load 3.40
> 2.99
> 2.65]
> ... yada yada yada ...
> Pending 2, Ready 0, Running 1, Retrying 0, Total 22 [Time 45m32.9s Load
> 1.00
> 1.18 2.95]
>
> From the above output, we see that a package is building for a long time,
> but
> we don't know what package. We should output the package name every two
> minutes
> at least so people know what package is taking so long. That's what this
> change
> implements.
>
> BUG=chromium-os:8575
> TEST=Confirmed new status appear for regular build_packages. Confirmed
>     build_packages --showoutput is unchanged.
>
> Change-Id: Ie18b23ac7a8a6e2c24b43ec3691606c7da5e43cb
>
> Please review this at http://codereview.chromium.org/4318003/show
>
> SVN Base: ssh://git@gitrw.chromium.org:9222/crosutils.git
>
> Affected files:
>  M parallel_emerge
>
>
> Index: parallel_emerge
> diff --git a/parallel_emerge b/parallel_emerge
> index
>
acf17fb2d67493130f23a241ba5b8ccf76af4298..66b2334da64a8fa55118e4ab9389237b481ff62e
> 100755
> --- a/parallel_emerge
> +++ b/parallel_emerge
> @@ -1235,8 +1235,9 @@ def PrintDepsMap(deps_map):
>
>
>  class EmergeJobState(object):
> -  __slots__ = ["done", "filename", "last_output_seek",
> "last_output_timestamp",
> -               "pkgname", "retcode", "start_timestamp", "target"]
> +  __slots__ = ["done", "filename", "last_notify_timestamp",
> "last_output_seek",
> +               "last_output_timestamp", "pkgname", "retcode",
> "start_timestamp",
> +               "target"]
>
>   def __init__(self, target, pkgname, done, filename, start_timestamp,
>                retcode=None):
> @@ -1254,6 +1255,11 @@ class EmergeJobState(object):
>     # The filename where output is currently stored.
>     self.filename = filename
>
> +    # The timestamp of the last time we printed the name of the log file.
> We
> +    # print this at the beginning of the job, so this starts at
> +    # start_timestamp.
> +    self.last_notify_timestamp = start_timestamp
> +
>     # The location (in bytes) of the end of the last complete line we
> printed.
>     # This starts off at zero. We use this to jump to the right place when
> we
>     # print output from the same ebuild multiple times.
> @@ -1549,26 +1555,43 @@ class EmergeQueue(object):
>   def _Status(self):
>     """Print status."""
>     current_time = time.time()
> -    seconds = current_time - GLOBAL_START
> -    line = ("Pending %s, Ready %s, Running %s, Retrying %s, Total %s "
> -            "[Time %dm%.1fs Load %s]")
> -    qsize = self._emerge_queue.qsize()
> -    self._Print(line % (len(self._deps_map), qsize, len(self._jobs) -
> qsize,
> -                        len(self._retry_queue), self._total_jobs,
> -                        seconds / 60, seconds % 60, self._LoadAvg()))
> +    no_output = True
>
>     # Print interim output every minute if --show-output is used.
> Otherwise,
> -    # only print output if a job has been running for 60 minutes or more.
> +    # print notifications about running packages every 2 minutes, and
> print
> +    # full output for jobs that have been running for 60 minutes or more.
>     if self._show_output:
>       interval = 60
> +      notify_interval = 0
>     else:
>       interval = 60 * 60
> +      notify_interval = 60 * 2
>     for target, job in self._jobs.iteritems():
>       if job:
>         last_timestamp = max(job.start_timestamp,
> job.last_output_timestamp)
>         if last_timestamp + interval < current_time:
>           self._print_queue.put(JobPrinter(job))
>           job.last_output_timestamp = current_time
> +          no_output = False
> +        elif (notify_interval and
> +              job.last_notify_timestamp + notify_interval < current_time):
> +          job_seconds = current_time - job.start_timestamp
> +          args = (job.pkgname, job_seconds / 60, job_seconds % 60,
> job.filename)
> +          info = "Still building %s (%dm%.1fs). Logs in %s" % args
> +          job.last_notify_timestamp = current_time
> +          self._Print(info)
> +          no_output = False
> +
> +    # If we haven't printed any messages yet, print a general status
> message
> +    # here.
> +    if no_output:
> +      seconds = current_time - GLOBAL_START
> +      line = ("Pending %s, Ready %s, Running %s, Retrying %s, Total %s "
> +              "[Time %dm%.1fs Load %s]")
> +      qsize = self._emerge_queue.qsize()
> +      self._Print(line % (len(self._deps_map), qsize, len(self._jobs) -
> qsize,
> +                          len(self._retry_queue), self._total_jobs,
> +                          seconds / 60, seconds % 60, self._LoadAvg()))
>
>   def _Finish(self, target):
>     """Mark a target as completed and unblock dependecies."""
>
>
>

[Nick Sanders, 2010-11-02 21:37:10]

lgtm

[davidjames, 2010-11-02 21:44:41]

On 2010/11/02 20:07:58, kliegs wrote:
> I'd say print info for any job more than 10 minutes.  An hour is a long time
> to wait But only print the job list every 5 minutes
> 
> Although I expect you'll find many people with their own opinion on the
> right intervals :)

So, we're not printing out a whole job list. We're just replacing the "Pending
..." message with the name of one of the packages that's currently being built.
And we only print this for packages that take more than 2 minutes to build.
Given that the 'Pending... ' message appears every 5 seconds, the names of
packages are only going to be printed occasionally. I also, in this case,
removed the 'Pending...' message so that you don't get any more output, but do
get more information.

As for printing the full output, that actually can be a lot of output, so we
want to restrict that output to when users are using --showoutput unless the
build is taking an exceptionally long time and we need the info for debugging.
The intent of the 1hr number was to be big enough such that successful jobs
other than Chrome would never print any output, because nobody other than Chrome
takes longer than an hour to build. Not sure if that's still the right number,
but it can be tweaked if necessary. The disadvantage of making it smaller is
that we'll be adding output to the build that doesn't get removed when the user
specifies --noshowoutput

[kliegs, 2010-11-02 21:48:57]

Ok - I misread the comments about the intent.  Comments withdrawn.  

On 2010/11/02 21:44:41, davidjames wrote:
> On 2010/11/02 20:07:58, kliegs wrote:
> > I'd say print info for any job more than 10 minutes.  An hour is a long time
> > to wait But only print the job list every 5 minutes
> > 
> > Although I expect you'll find many people with their own opinion on the
> > right intervals :)
> 
> So, we're not printing out a whole job list. We're just replacing the "Pending
> ..." message with the name of one of the packages that's currently being
built.
> And we only print this for packages that take more than 2 minutes to build.
> Given that the 'Pending... ' message appears every 5 seconds, the names of
> packages are only going to be printed occasionally. I also, in this case,
> removed the 'Pending...' message so that you don't get any more output, but do
> get more information.
> 
> As for printing the full output, that actually can be a lot of output, so we
> want to restrict that output to when users are using --showoutput unless the
> build is taking an exceptionally long time and we need the info for debugging.
> The intent of the 1hr number was to be big enough such that successful jobs
> other than Chrome would never print any output, because nobody other than
Chrome
> takes longer than an hour to build. Not sure if that's still the right number,
> but it can be tweaked if necessary. The disadvantage of making it smaller is
> that we'll be adding output to the build that doesn't get removed when the
user
> specifies --noshowoutput

[anush, 2010-11-02 21:51:52]

LGTM. Please commit to .110.B too. 

On 2010/11/02 21:48:57, kliegs wrote:
> Ok - I misread the comments about the intent.  Comments withdrawn.  
> 
> On 2010/11/02 21:44:41, davidjames wrote:
> > On 2010/11/02 20:07:58, kliegs wrote:
> > > I'd say print info for any job more than 10 minutes.  An hour is a long
time
> > > to wait But only print the job list every 5 minutes
> > > 
> > > Although I expect you'll find many people with their own opinion on the
> > > right intervals :)
> > 
> > So, we're not printing out a whole job list. We're just replacing the
"Pending
> > ..." message with the name of one of the packages that's currently being
> built.
> > And we only print this for packages that take more than 2 minutes to build.
> > Given that the 'Pending... ' message appears every 5 seconds, the names of
> > packages are only going to be printed occasionally. I also, in this case,
> > removed the 'Pending...' message so that you don't get any more output, but
do
> > get more information.
> > 
> > As for printing the full output, that actually can be a lot of output, so we
> > want to restrict that output to when users are using --showoutput unless the
> > build is taking an exceptionally long time and we need the info for
debugging.
> > The intent of the 1hr number was to be big enough such that successful jobs
> > other than Chrome would never print any output, because nobody other than
> Chrome
> > takes longer than an hour to build. Not sure if that's still the right
number,
> > but it can be tweaked if necessary. The disadvantage of making it smaller is
> > that we'll be adding output to the build that doesn't get removed when the
> user
> > specifies --noshowoutput