pt-heartbeat --utc --check always returns 0

Bug #1163372 reported by Jeff Sheltren on 2013-04-02
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Percona Toolkit moved to https://jira.percona.com/projects/PT
Fix Released
Medium
Daniel Nichter
2.1
Fix Released
Medium
Daniel Nichter
2.2
Fix Released
Medium
Daniel Nichter

Bug Description

I'm trying to use pt-heartbeat 2.2 with the new --utc option since the servers have different timezones. When running on the slave, pt-heartbeat --check always prints out "0", no matter how old the timestamp is in the heartbeat table.

I'm setting this on the master with:
/usr/bin/pt-heartbeat -D heartbeat --update --run-time 3 --utc

Checking on the slave with:
/usr/bin/pt-heartbeat --utc -D heartbeat --check

After setting it on the master, running on the slave gives this:

# /usr/bin/pt-heartbeat --utc -D heartbeat --check
0

Even after waiting a few minutes, the result is the same. I can verify that the timestamp is set properly on the master by setting it manually, and switching to the slave:
# date -u && mysql -e "select ts from heartbeat\G" heartbeat
Tue Apr 2 15:08:36 UTC 2013
*************************** 1. row ***************************
ts: 2013-04-02 15:08:35

To get more information, I set PTDEBUG and ran pt-heartbeat again on master to update, and then the check outputs the following (truncated) debug info:

# TableParser:2872 2817 Storage engine: InnoDB
# TableParser:2726 2817 Table cols: `id`, `ts`
# TableParser:2872 2817 Storage engine: InnoDB
# TableParser:2888 2817 Parsed key: PRIMARY KEY (`id`)
# TableParser:2908 2817 PRIMARY key cols: `id`
# TableParser:2930 2817 This key is the clustered key
# pt_heartbeat:4886 2817 Hi-res ts: no
# pt_heartbeat:4951 2817 Heartbeat row primary key: id = 1
# pt_heartbeat:4957 2817 SELECT 1 FROM `heartbeat`.`heartbeat` WHERE id='1' LIMIT 1
# pt_heartbeat:5097 2817 SELECT SQL: SELECT UNIX_TIMESTAMP(ts)/*!50038, @@hostname AS host*/ FROM `heartbeat`.`heartbeat` WHERE id='1' LIMIT 1
# pt_heartbeat:5104 2817 SELECT UNIX_TIMESTAMP(ts)/*!50038, @@hostname AS host*/ FROM `heartbeat`.`heartbeat` WHERE id='1' LIMIT 1
# pt_heartbeat:5107 2817 Heartbeat from server undef
# now: 2013-04-02T15:12:06.851010
# ts: 1364929924
# skew: 0.5
# pt_heartbeat:5112 2817 Delay -14397.648988 on foo.bar.com
# pt_heartbeat:5153 2817 --check and exit
# pt_heartbeat:5296 2817 Checking slave delay
# pt_heartbeat:5336 2817 Checking slave D=heartbeat
# pt_heartbeat:5346 2817 Woke up at 2013-04-02T11:12:07.500460
# pt_heartbeat:5104 2817 SELECT UNIX_TIMESTAMP(ts)/*!50038, @@hostname AS host*/ FROM `heartbeat`.`heartbeat` WHERE id='1' LIMIT 1
# pt_heartbeat:5107 2817 Heartbeat from server undef
# now: 2013-04-02T15:12:07.500690
# ts: 1364929924
# skew: 0.5
# pt_heartbeat:5112 2817 Delay -14396.999310 on foo.bar.com
0
# pt_heartbeat:5391 2817 Disconnecting

Note that the slave server is 4 hours behind UTC (US Eastern), so the delay in the debug info matches that pretty much exactly. Seems like the check isn't respecting --utc, and since the delay is negative, it prints out 0.

Related branches

Jeff Sheltren (jeffsheltren) wrote :

Forgot to mention, this is percona-toolkit-2.2.1-2 on RHEL 5.9, MySQL 5.5.29

Daniel Nichter (daniel-nichter) wrote :

Thanks for reporting this, Jeff. We'll look into it soon.

Changed in percona-toolkit:
status: New → Confirmed
importance: Undecided → Medium
assignee: nobody → Daniel Nichter (daniel-nichter)
milestone: none → 2.2.2
tags: added: pt-heartbeat
summary: - pt-heartbeat 2.2.1 check always returns 0
+ pt-heartbeat --utc --check always returns 0
tags: added: tz wrong-output
Daniel Nichter (daniel-nichter) wrote :

Indeed, the problem is that https://dev.mysql.com/doc/refman/5.5/en/date-and-time-functions.html#function_unix-timestamp :

"""
The server interprets date as a value in the current time zone and converts it to an internal value in UTC.
"""

So the tools need to SET time_zone='+0:00'; so that UNIX_TIMESTAMP() returns the ts from the server as UTC (and it was inserted as UTC using UTC_TIMESTAMP()).

Daniel Nichter (daniel-nichter) wrote :

This has been tested and fixed. It will be released soon in 2.2.2 and, later, 2.1.10.

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PT-609

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers