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

Bug #1163372 reported by Jeff Sheltren
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

Revision history for this message
Jeff Sheltren (jeffsheltren) wrote :

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

Revision history for this message
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
Revision history for this message
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()).

Revision history for this message
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.

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.