Prevent TimeUntilNextProcess log spam.

Prevent TimeUntilNextProcess log spam.

Negative values from TimeUntilNextProcess indicate that the module
wanted to run sooner than possible, not that an invalid error code was
returned. As such it's not a contract error.

BUG=webrtc:4879
NOTRY=true

Committed: https://crrev.com/9e260f184b2ce0d4316267bf5464795dfd8ac883
Cr-Commit-Position: refs/heads/master@{#9740}

[pbos-webrtc, 2015-07-29 08:23:15]

pbos@webrtc.org changed reviewers:
- tommi@webrtc.org

[stefan-webrtc, 2015-07-29 08:40:15]

stefan@webrtc.org changed reviewers:
+ stefan@webrtc.org

[stefan-webrtc, 2015-07-29 08:40:16]

lgtm

[juberti1, 2015-07-29 18:19:55]

juberti@webrtc.org changed reviewers:
+ juberti@webrtc.org

[juberti1, 2015-07-29 18:19:55]

the comment seems to indicate that this is in fact an error, so not sure we
should stop logging completely, but I was hoping we would only log at most N
times (using a member var to keep track of how often we have logged).

For now, perhaps N=10, or some such

[stefan-webrtc, 2015-07-30 08:58:19]

On 2015/07/29 18:19:55, juberti1 wrote:
> the comment seems to indicate that this is in fact an error, so not sure we
> should stop logging completely, but I was hoping we would only log at most N
> times (using a member var to keep track of how often we have logged).
> 
> For now, perhaps N=10, or some such

Our thinking is that it isn't really an error that the scheduler is falling
behind. There could be some heavy task taking time, which results in other tasks
being delayed. We could log it as a warning, but I suspect that this is likely
to happen every now and then in most calls.

I can however see that it could be useful to know if we frequently have very
delayed tasks. Maybe we could have a threshold and log every Nth time a task is
delayed for more than, say, 20 ms?

[pbos-webrtc, 2015-07-30 09:15:40]

On 2015/07/30 08:58:19, stefan-webrtc (holmer) wrote:
> On 2015/07/29 18:19:55, juberti1 wrote:
> > the comment seems to indicate that this is in fact an error, so not sure we
> > should stop logging completely, but I was hoping we would only log at most N
> > times (using a member var to keep track of how often we have logged).
> > 
> > For now, perhaps N=10, or some such
> 
> Our thinking is that it isn't really an error that the scheduler is falling
> behind. There could be some heavy task taking time, which results in other
tasks
> being delayed. We could log it as a warning, but I suspect that this is likely
> to happen every now and then in most calls.
> 
> I can however see that it could be useful to know if we frequently have very
> delayed tasks. Maybe we could have a threshold and log every Nth time a task
is
> delayed for more than, say, 20 ms?

I also don't think this is an error, a -1 here should not be an error code as
far as I can tell. A common implementation of this could be:

Process(): {
  ...
  next_run_ms_ = Clock::NowMs() + 20;
}

TimeUntilNextProcess() {
  return next_run_ms_ - Clock::NowMs();
}

I don't think it's useful to enforce clamping by the module in this case, but if
the process module falls behind this is something we'll log.

[stefan-webrtc, 2015-07-30 09:29:02]

On 2015/07/30 09:15:40, pbos-webrtc wrote:
> On 2015/07/30 08:58:19, stefan-webrtc (holmer) wrote:
> > On 2015/07/29 18:19:55, juberti1 wrote:
> > > the comment seems to indicate that this is in fact an error, so not sure
we
> > > should stop logging completely, but I was hoping we would only log at most
N
> > > times (using a member var to keep track of how often we have logged).
> > > 
> > > For now, perhaps N=10, or some such
> > 
> > Our thinking is that it isn't really an error that the scheduler is falling
> > behind. There could be some heavy task taking time, which results in other
> tasks
> > being delayed. We could log it as a warning, but I suspect that this is
likely
> > to happen every now and then in most calls.
> > 
> > I can however see that it could be useful to know if we frequently have very
> > delayed tasks. Maybe we could have a threshold and log every Nth time a task
> is
> > delayed for more than, say, 20 ms?
> 
> I also don't think this is an error, a -1 here should not be an error code as
> far as I can tell. A common implementation of this could be:
> 
> Process(): {
>   ...
>   next_run_ms_ = Clock::NowMs() + 20;
> }
> 
> TimeUntilNextProcess() {
>   return next_run_ms_ - Clock::NowMs();
> }
> 
> I don't think it's useful to enforce clamping by the module in this case, but
if
> the process module falls behind this is something we'll log.

I agree. We'd prefer to let the process module know that tasks are falling
behind than to leave it to each module to clamp the time.

[tommi, 2015-08-04 11:38:36]

On 2015/07/30 09:29:02, stefan-webrtc (holmer) wrote:
> On 2015/07/30 09:15:40, pbos-webrtc wrote:
> > On 2015/07/30 08:58:19, stefan-webrtc (holmer) wrote:
> > > On 2015/07/29 18:19:55, juberti1 wrote:
> > > > the comment seems to indicate that this is in fact an error, so not sure
> we
> > > > should stop logging completely, but I was hoping we would only log at
most
> N
> > > > times (using a member var to keep track of how often we have logged).
> > > > 
> > > > For now, perhaps N=10, or some such
> > > 
> > > Our thinking is that it isn't really an error that the scheduler is
falling
> > > behind. There could be some heavy task taking time, which results in other
> > tasks
> > > being delayed. We could log it as a warning, but I suspect that this is
> likely
> > > to happen every now and then in most calls.
> > > 
> > > I can however see that it could be useful to know if we frequently have
very
> > > delayed tasks. Maybe we could have a threshold and log every Nth time a
task
> > is
> > > delayed for more than, say, 20 ms?
> > 
> > I also don't think this is an error, a -1 here should not be an error code
as
> > far as I can tell. A common implementation of this could be:
> > 
> > Process(): {
> >   ...
> >   next_run_ms_ = Clock::NowMs() + 20;
> > }
> > 
> > TimeUntilNextProcess() {
> >   return next_run_ms_ - Clock::NowMs();
> > }
> > 
> > I don't think it's useful to enforce clamping by the module in this case,
but
> if
> > the process module falls behind this is something we'll log.
> 
> I agree. We'd prefer to let the process module know that tasks are falling
> behind than to leave it to each module to clamp the time.

There are implementations that are (or at least were) returning errors, and not
"back in time" values.  I suppose it may be a mix.
There's no point in telling the scheduler though that tasks are falling behind
and there's nothing the scheduler can do about it, so I don't think these are
right.  The main concern however was around the places that were returning error
values and not time values and that's why the log exists.

[stefan-webrtc, 2015-08-04 14:43:04]

On 2015/08/04 11:38:36, tommi (webrtc) wrote:
> On 2015/07/30 09:29:02, stefan-webrtc (holmer) wrote:
> > On 2015/07/30 09:15:40, pbos-webrtc wrote:
> > > On 2015/07/30 08:58:19, stefan-webrtc (holmer) wrote:
> > > > On 2015/07/29 18:19:55, juberti1 wrote:
> > > > > the comment seems to indicate that this is in fact an error, so not
sure
> > we
> > > > > should stop logging completely, but I was hoping we would only log at
> most
> > N
> > > > > times (using a member var to keep track of how often we have logged).
> > > > > 
> > > > > For now, perhaps N=10, or some such
> > > > 
> > > > Our thinking is that it isn't really an error that the scheduler is
> falling
> > > > behind. There could be some heavy task taking time, which results in
other
> > > tasks
> > > > being delayed. We could log it as a warning, but I suspect that this is
> > likely
> > > > to happen every now and then in most calls.
> > > > 
> > > > I can however see that it could be useful to know if we frequently have
> very
> > > > delayed tasks. Maybe we could have a threshold and log every Nth time a
> task
> > > is
> > > > delayed for more than, say, 20 ms?
> > > 
> > > I also don't think this is an error, a -1 here should not be an error code
> as
> > > far as I can tell. A common implementation of this could be:
> > > 
> > > Process(): {
> > >   ...
> > >   next_run_ms_ = Clock::NowMs() + 20;
> > > }
> > > 
> > > TimeUntilNextProcess() {
> > >   return next_run_ms_ - Clock::NowMs();
> > > }
> > > 
> > > I don't think it's useful to enforce clamping by the module in this case,
> but
> > if
> > > the process module falls behind this is something we'll log.
> > 
> > I agree. We'd prefer to let the process module know that tasks are falling
> > behind than to leave it to each module to clamp the time.
> 
> There are implementations that are (or at least were) returning errors, and
not
> "back in time" values.  I suppose it may be a mix.
> There's no point in telling the scheduler though that tasks are falling behind
> and there's nothing the scheduler can do about it, so I don't think these are
> right.  The main concern however was around the places that were returning
error
> values and not time values and that's why the log exists.

I see, thanks for that input.

The main reason we would like to accept negative values is to avoid having code
for clamping to 0 in each module separately. Were the modules returning errors
fixed, or are they still around?

[juberti1, 2015-08-13 20:49:32]

On 2015/08/04 14:43:04, stefan-webrtc (holmer) wrote:
> On 2015/08/04 11:38:36, tommi (webrtc) wrote:
> > On 2015/07/30 09:29:02, stefan-webrtc (holmer) wrote:
> > > On 2015/07/30 09:15:40, pbos-webrtc wrote:
> > > > On 2015/07/30 08:58:19, stefan-webrtc (holmer) wrote:
> > > > > On 2015/07/29 18:19:55, juberti1 wrote:
> > > > > > the comment seems to indicate that this is in fact an error, so not
> sure
> > > we
> > > > > > should stop logging completely, but I was hoping we would only log
at
> > most
> > > N
> > > > > > times (using a member var to keep track of how often we have
logged).
> > > > > > 
> > > > > > For now, perhaps N=10, or some such
> > > > > 
> > > > > Our thinking is that it isn't really an error that the scheduler is
> > falling
> > > > > behind. There could be some heavy task taking time, which results in
> other
> > > > tasks
> > > > > being delayed. We could log it as a warning, but I suspect that this
is
> > > likely
> > > > > to happen every now and then in most calls.
> > > > > 
> > > > > I can however see that it could be useful to know if we frequently
have
> > very
> > > > > delayed tasks. Maybe we could have a threshold and log every Nth time
a
> > task
> > > > is
> > > > > delayed for more than, say, 20 ms?
> > > > 
> > > > I also don't think this is an error, a -1 here should not be an error
code
> > as
> > > > far as I can tell. A common implementation of this could be:
> > > > 
> > > > Process(): {
> > > >   ...
> > > >   next_run_ms_ = Clock::NowMs() + 20;
> > > > }
> > > > 
> > > > TimeUntilNextProcess() {
> > > >   return next_run_ms_ - Clock::NowMs();
> > > > }
> > > > 
> > > > I don't think it's useful to enforce clamping by the module in this
case,
> > but
> > > if
> > > > the process module falls behind this is something we'll log.
> > > 
> > > I agree. We'd prefer to let the process module know that tasks are falling
> > > behind than to leave it to each module to clamp the time.
> > 
> > There are implementations that are (or at least were) returning errors, and
> not
> > "back in time" values.  I suppose it may be a mix.
> > There's no point in telling the scheduler though that tasks are falling
behind
> > and there's nothing the scheduler can do about it, so I don't think these
are
> > right.  The main concern however was around the places that were returning
> error
> > values and not time values and that's why the log exists.
> 
> I see, thanks for that input.
> 
> The main reason we would like to accept negative values is to avoid having
code
> for clamping to 0 in each module separately. Were the modules returning errors
> fixed, or are they still around?

Any updates on this? Agree we shouldn't log on falling behind, but would be good
to report when an error is (incorrectly) returned. Is there any way to do this?

[pbos-webrtc, 2015-08-19 00:30:02]

On 2015/08/13 20:49:32, juberti1 wrote:
> On 2015/08/04 14:43:04, stefan-webrtc (holmer) wrote:
> > On 2015/08/04 11:38:36, tommi (webrtc) wrote:
> > > On 2015/07/30 09:29:02, stefan-webrtc (holmer) wrote:
> > > > On 2015/07/30 09:15:40, pbos-webrtc wrote:
> > > > > On 2015/07/30 08:58:19, stefan-webrtc (holmer) wrote:
> > > > > > On 2015/07/29 18:19:55, juberti1 wrote:
> > > > > > > the comment seems to indicate that this is in fact an error, so
not
> > sure
> > > > we
> > > > > > > should stop logging completely, but I was hoping we would only log
> at
> > > most
> > > > N
> > > > > > > times (using a member var to keep track of how often we have
> logged).
> > > > > > > 
> > > > > > > For now, perhaps N=10, or some such
> > > > > > 
> > > > > > Our thinking is that it isn't really an error that the scheduler is
> > > falling
> > > > > > behind. There could be some heavy task taking time, which results in
> > other
> > > > > tasks
> > > > > > being delayed. We could log it as a warning, but I suspect that this
> is
> > > > likely
> > > > > > to happen every now and then in most calls.
> > > > > > 
> > > > > > I can however see that it could be useful to know if we frequently
> have
> > > very
> > > > > > delayed tasks. Maybe we could have a threshold and log every Nth
time
> a
> > > task
> > > > > is
> > > > > > delayed for more than, say, 20 ms?
> > > > > 
> > > > > I also don't think this is an error, a -1 here should not be an error
> code
> > > as
> > > > > far as I can tell. A common implementation of this could be:
> > > > > 
> > > > > Process(): {
> > > > >   ...
> > > > >   next_run_ms_ = Clock::NowMs() + 20;
> > > > > }
> > > > > 
> > > > > TimeUntilNextProcess() {
> > > > >   return next_run_ms_ - Clock::NowMs();
> > > > > }
> > > > > 
> > > > > I don't think it's useful to enforce clamping by the module in this
> case,
> > > but
> > > > if
> > > > > the process module falls behind this is something we'll log.
> > > > 
> > > > I agree. We'd prefer to let the process module know that tasks are
falling
> > > > behind than to leave it to each module to clamp the time.
> > > 
> > > There are implementations that are (or at least were) returning errors,
and
> > not
> > > "back in time" values.  I suppose it may be a mix.
> > > There's no point in telling the scheduler though that tasks are falling
> behind
> > > and there's nothing the scheduler can do about it, so I don't think these
> are
> > > right.  The main concern however was around the places that were returning
> > error
> > > values and not time values and that's why the log exists.
> > 
> > I see, thanks for that input.
> > 
> > The main reason we would like to accept negative values is to avoid having
> code
> > for clamping to 0 in each module separately. Were the modules returning
errors
> > fixed, or are they still around?
> 
> Any updates on this? Agree we shouldn't log on falling behind, but would be
good
> to report when an error is (incorrectly) returned. Is there any way to do
this?

I don't believe they were ever errors really. Stefan do you think that's the
case?

This means that all values are valid and as such we can't detect any of them as
erroneous (-1 which might have been used if that's the case is valid use). I'm
still on vacation this week so if you want it in like this then CQ it as my
email checking is very sparse.

[tommi (sloooow) - chröme, 2015-08-19 12:50:15]

tommi@chromium.org changed reviewers:
+ tommi@chromium.org

[tommi (sloooow) - chröme, 2015-08-19 12:50:15]

The CQ bit was checked by tommi@chromium.org

[tommi (sloooow) - chröme, 2015-08-19 12:50:16]

lgtm

[commit-bot: I haz the power, 2015-08-19 12:50:25]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1257833004/1
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1257833004/1

[tommi (sloooow) - chröme, 2015-08-19 12:51:00]

On 2015/08/19 12:50:16, tommi wrote:
> lgtm

I figured we should just get this in now and I'll circle back to see the places
that I was talking about.

[commit-bot: I haz the power, 2015-08-19 12:52:01]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2015-08-19 12:52:02]

Try jobs failed on following builders:
  presubmit on tryserver.webrtc (JOB_FAILED,
http://build.chromium.org/p/tryserver.webrtc/builders/presubmit/builds/405)

[tommi, 2015-08-19 12:59:39]

tommi@webrtc.org changed reviewers:
+ tommi@webrtc.org

[tommi, 2015-08-19 12:59:39]

The CQ bit was checked by tommi@webrtc.org

[tommi, 2015-08-19 12:59:40]

lgtm

bah, signed in with the wrong account...hrmpf.

[commit-bot: I haz the power, 2015-08-19 12:59:47]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1257833004/1
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1257833004/1

[commit-bot: I haz the power, 2015-08-19 14:50:35]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2015-08-19 14:50:36]

Try jobs failed on following builders:
  android on tryserver.webrtc (JOB_TIMED_OUT, no build URL)

[tommi, 2015-08-19 15:09:46]

The CQ bit was checked by tommi@webrtc.org

[commit-bot: I haz the power, 2015-08-19 15:09:55]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1257833004/1
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1257833004/1

[commit-bot: I haz the power, 2015-08-19 17:10:10]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2015-08-19 17:10:10]

Try jobs failed on following builders:
  android on tryserver.webrtc (JOB_TIMED_OUT, no build URL)

[juberti1, 2015-08-20 04:58:32]

lgtm

[tommi, 2015-08-20 06:12:13]

The CQ bit was checked by tommi@webrtc.org

[commit-bot: I haz the power, 2015-08-20 06:12:27]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1257833004/1
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1257833004/1

[commit-bot: I haz the power, 2015-08-20 08:12:34]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2015-08-20 08:12:35]

Try jobs failed on following builders:
  android on tryserver.webrtc (JOB_TIMED_OUT, no build URL)

[tommi (sloooow) - chröme, 2015-08-20 08:22:45]

something is up with the cq. bringing out hammer.

[tommi (sloooow) - chröme, 2015-08-20 08:22:50]

The CQ bit was checked by tommi@chromium.org

[commit-bot: I haz the power, 2015-08-20 08:23:04]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1257833004/1
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1257833004/1

[commit-bot: I haz the power, 2015-08-20 08:23:53]

Committed patchset #1 (id:1)

[commit-bot: I haz the power, 2015-08-20 08:24:02]

Patchset 1 (id:??) landed as
https://crrev.com/9e260f184b2ce0d4316267bf5464795dfd8ac883
Cr-Commit-Position: refs/heads/master@{#9740}