Java Timer fires out of band

Question

I created a Java class that checks every minute whether some heartbeat signal has arrived though some queue. While this so far has worked well a strange case was reported from production where there is an entry in the log every ms or even twice in a ms. This went on for about 40 min, till the admin detected the problem and restarted the application. Therafter, the heartbeat queue was ckecked again every minute according to the log which is the expected behavior.

The problematic log entries looks (simplified) like this:

16-03-2021 01:20:20.098 HEARTBEAT_NOT_OK. No initial heartbeat from server after application startup at 01.01.1970-00:01:09.444 for 18702 day(s) 01:19:10 (days hh:mm:ss). Heartbeat interval 60000 ms.
16-03-2021 01:20:20.099 HEARTBEAT_NOT_OK. No initial heartbeat from server after application startup at 01.01.1970-00:01:09.444 for 18702 day(s) 01:19:10 (days hh:mm:ss). Heartbeat interval 60000 ms.
16-03-2021 01:20:20.099 HEARTBEAT_NOT_OK. No initial heartbeat from server after application startup at 01.01.1970-00:01:09.444 for 18702 day(s) 01:19:10 (days hh:mm:ss). Heartbeat interval 60000 ms.
16-03-2021 01:20:20.100 HEARTBEAT_NOT_OK. No initial heartbeat from server after application startup at 01.01.1970-00:01:09.444 for 18702 day(s) 01:19:10 (days hh:mm:ss). Heartbeat interval 60000 ms.

The log text is always the same, for which I cannot find an explanation. Here is the simplified code of that Java class that should ckeck the hearbeat queue every minute:

@Slf4j
@Component(service = ServiceProvider.class)
public class HeartbeatReceiver implements ServiceProvider {

private static DateFormat DateFormatter = new SimpleDateFormat("dd.MM.yyyy-HH:mm:ss.SSS");
private static long DefaultHeartbeatPeriodInMillis = 60_000;

private Timer timer;
private ReceivedHeartbeat lastHeartbeat = null;
private long heartbeatPeriod = DefaultHeartbeatPeriodInMillis;
private Object heartbeatPeriodLock = new Object();
private volatile long watchdogStartTime;
private Object heartbeatAliveLock = new Object();


@Activate
public void activate() {
    startWatchdog();
}

private void startWatchdog() {
    watchdogStartTime = System.currentTimeMillis();
    startWatchdogTimer();
}

private void startWatchdogTimer() {
    timer = new Timer();
    timer.scheduleAtFixedRate(new TimerTask() {
        @Override
        public void run() {
            checkHeartbeat();
        }
    }, delayTillFullMinute(), getHeartbeatPeriod());
}

private long delayTillFullMinute() {
    return 0; // omitted for brevity
}

public long getHeartbeatPeriod() {
    synchronized (heartbeatPeriodLock) {
        return heartbeatPeriod;
    }
}

private void checkHeartbeat() {
    synchronized (heartbeatAliveLock) {
        if (lastHeartbeat == null) { // just started up
            long duration = System.currentTimeMillis() - watchdogStartTime;
            if(duration >= heartbeatPeriod) {
                logNoInitialHeartbeatReceivedAfterStartup(duration);
            }
            // omitted for brevity
            return;
        }

        // omitted for brevity
    }
}

private void logNoInitialHeartbeatReceivedAfterStartup(long duration) {
    log.error("HEARTBEAT_NOT_OK. No initial heartbeat from server after application startup at {} for {}. Heartbeat interval {} ms.",
        DateFormatter.format(watchdogStartTime), parseTime(duration), heartbeatPeriod);
}

public static String parseTime(long time) {
    return "foo"; // omitted for brevity
}

// other code omitted for brevity

}

My guess is that the OSGi @Activate annotation causes some class initialization problem, because of which var heartbeatPeriod is not initialized correctly. But then the log output should show the date 01.01.1970-00:00:00.000 and not 01.01.1970-00:01:09.444. This strange date 01.01.1970-00:01:09.444 also puzzles me.

user_243991 · Answer

You are creating a Timer task but you never cancel it on a deactivate. (Nor close the Timer itself, which will keep occupying a thread.)

So are you sure that this is not an old Timer running?

user_7192440 · Answer

Just a wild guess, but you are synchronizing on

private Object heartbeatAliveLock = new Object();

Why not synchronize on

private HeartbeatReceiver heartbeatAliveLock  = null;
.
.
.
public HeartbeatReceiver()
{
   super();

   heartbeatAliveLock = this;
}

user_448551 · Answer

01.01.1970 is the epoch time. That is, 0L. If you are really interested in elapsed time, then I would suggest using System.nanoTime instead which is much safer for elapsed time calculations. System.currentTimeMillis is for knowing the system time which can be changed while you are running.

Java Timer fires out of band

3 Answers