MySQL Bugs: #36819: ut_usectime does not handle errors from gettimeofday

Bug #36819	ut_usectime does not handle errors from gettimeofday
Submitted:	20 May 2008 15:57	Modified:	20 Jun 2010 0:55
Reporter:	Mark Callaghan	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.0.37, 5.1	OS:	Linux
Assigned to:		CPU Architecture:	Any
Tags:	gettimeofday, innodb, ut_usectime

Description:
The code for ut_usectime ignores errors returned by gettimeofday. gettimeofday fails intermittently on my servers and the man page states that it can fail.

void
ut_usectime(
/*========*/
  ulint*  sec,  /* out: seconds since the Epoch */
  ulint*  ms) /* out: microseconds since the Epoch+*sec */
{
#ifdef __WIN__
  SYSTEMTIME st;
  GetLocalTime(&st);
  *sec = (ulint) st.wSecond;
  *ms  = (ulint) st.wMilliseconds;
#else
  struct timeval  tv;
  gettimeofday(&tv,NULL);
  *sec = (ulint) tv.tv_sec;
  *ms  = (ulint) tv.tv_usec;
#endif
}

How to repeat:
Modify ut_usectime to check the error return value and log a message when an error occurs.

Suggested fix:
Check the return value of gettimeofday

Vasil,

please fix this little bug.

http://nixdoc.net/man-pages/Linux/gettimeofday.2.html

"
RETURN VALUE    [Toc]    [Back]
       gettimeofday  and  settimeofday return 0 for success, or -1 for failure
       (in which case errno is set appropriately).
ERRORS    [Toc]    [Back]
       EPERM  settimeofday is called by someone other than the superuser.

       EINVAL Timezone (or something else) is invalid.

       EFAULT One of tv or tz pointed outside your accessible address space.
"

Regards,

Heikki

Thank you for the bug report.

Mark,

would you be happy with an assert if gettimeofday(2) returns error?

I wonder what is the reason for it failing at all in the first place:

       EFAULT One of tv or tz pointed outside the accessible address space.

       EINVAL Timezone (or something else) is invalid.

       EPERM  The calling process has insufficient  privilege  to  call  settimeofday();
              under Linux the CAP_SYS_TIME capability is required.

EPERM cannot be because we are not calling settimeofday(2)
EINVAL cannot be because timezone is NULL and what "else"?
EFAULT tv is in the stack of the same function and tz is NULL

We are definitely going to print an error message with something like strerror(errno), but the question is how to proceed afterwards...

Mark, in 5.0 ut_usectime() is only used to update the variable innodb_row_lock_time_max in SHOW STATUS output.

Is your problem related to this variable? What do you see for its value?

Assert would be worse. It fails intermittently for reasons that I do not understand. The rate of failure is probably a few times per server per day and there are probably millions of calls to it per server per day.

I noticed this while looking at the IO accounting patch from Percona. They use the function to measure IO wait time. I agree it won't have much of an impact on current code.

Then the question is what to do if gettimeofday(2) fails, probably something like this makes most sense:

--- cut ---
int
ut_usectime(
/*========*/
                        /* out: 0 on success, -1 otherwise */
        ulint*  sec,    /* out: seconds since the Epoch */
        ulint*  ms)     /* out: microseconds since the Epoch+*sec */
{
        struct timeval  tv;
        int             ret;
        int             errno_gettimeofday;
        int             i;

        for (i = 0; i < 10; i++) {

                ret = ut_gettimeofday(&tv, NULL);

                if (ret == -1) { 
                        errno_gettimeofday = errno;
                        ut_print_timestamp(stderr);
                        fprintf(stderr, "  InnoDB: gettimeofday(): %s\n",
                                strerror(errno_gettimeofday));
                        os_thread_sleep(100000);  /* 0.1 sec */
                        errno = errno_gettimeofday;
                } else {
                        break;
                }
        }

        if (ret != -1) {
                *sec = (ulint) tv.tv_sec;
                *ms  = (ulint) tv.tv_usec;
        }

        return(ret);
}
--- cut ---

This retries several times and, if unsuccessful, propagates the error to the caller.

Merged into 6.0.6-alpha, according to Tim. But the patch has not been pushed into 5.0, 5.1 yet.

Noted in 6.0.6 changelog.

The code for the ut_usectime() function in InnoDB did not handle
errors from the gettimeofday() system call. Now it retries
gettimeofday() several times and updates the value of the
Innodb_row_lock_time_max status variable only if ut_usectime() was 
successful.

Setting report to Patch queued pending push of fix into 5.1.x or other trees.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/61571

2742 Timothy Smith	2008-12-12
      Apply the rest of innodb-5.0-ss2475.  This fixes Bug#36819, "ut_usectime does
      not handle errors from gettimeofday".
      
      r2475 | vasil | 2008-05-22 19:35:30 +0300 (Thu, 22 May 2008) | 13 lines
      
      Fix by retrying gettimeofday() several times if it fails in ut_usectime().
      If it fails on all calls then return error to the caller to be handled
      at higher level.
      
      Update the variable innodb_row_lock_time_max in SHOW STATUS output only
      if ut_usectime() was successful.

Pushed into 5.0.76 (revid:joro@sun.com-20090105160414-8q9j4bi1klkfwiup) (version source revid:azundris@mysql.com-20081230114734-nmsc37ak330zlygn) (merge vers: 5.0.76) (pib:6)

Noted in 5.0.76.

Setting report to NDI pending push into 5.1.x.

Pushed into 5.1.31 (revid:joro@sun.com-20090115053147-tx1oapthnzgvs1ro) (version source revid:azundris@mysql.com-20081230114838-cn52tu180wcrvh0h) (merge vers: 5.1.31) (pib:6)

Noted in 5.1.31 changelog.

Pushed into 5.1.31-ndb-6.2.17 (revid:tomas.ulin@sun.com-20090119095303-uwwvxiibtr38djii) (version source revid:tomas.ulin@sun.com-20090115073240-1wanl85vlvw2she1) (merge vers: 5.1.31-ndb-6.2.17) (pib:6)

Pushed into 5.1.31-ndb-6.3.21 (revid:tomas.ulin@sun.com-20090119104956-guxz190n2kh31fxl) (version source revid:tomas.ulin@sun.com-20090119104956-guxz190n2kh31fxl) (merge vers: 5.1.31-ndb-6.3.21) (pib:6)

Pushed into 5.1.31-ndb-6.4.1 (revid:tomas.ulin@sun.com-20090119144033-4aylstx5czzz88i5) (version source revid:tomas.ulin@sun.com-20090119144033-4aylstx5czzz88i5) (merge vers: 5.1.31-ndb-6.4.1) (pib:6)

Pushed into 6.0.10-alpha (revid:joro@sun.com-20090119171328-2hemf2ndc1dxl0et) (version source revid:azundris@mysql.com-20081230114916-c290n83z25wkt6e4) (merge vers: 6.0.9-alpha) (pib:6)

Pushed into 5.1.47 (revid:joro@sun.com-20100505145753-ivlt4hclbrjy8eye) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.

Pushed into mysql-next-mr (revid:alik@sun.com-20100524190136-egaq7e8zgkwb9aqi) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (pib:16)

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100524190941-nuudpx60if25wsvx) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.5.5-m3 (revid:alik@sun.com-20100524185725-c8k5q7v60i5nix3t) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.

Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)