Weird Time-recording problem

[Alex Edwards]

I'm getting ridiculous results in my program!

Seconds work fine
Decaseconds (1/10 of a second) work ok
Centiseconds seem a bit off
Milliseconds are completely off...

Here's the code--

import javax.swing.*;
import java.awt.event.*;

public class Clock{

	private Timer t;
	private long startTime = 0, finishTime = 0;
	private boolean isStarted = false;
	public static final int SECONDS = 0, DECASECONDS = 1, CENTISECONDS = 2, MILLISECONDS = 3;

	public Clock(int timeType){
		switch(timeType){
			case 0: t = new Timer(1000, al);
				break;
			case 1: t = new Timer(100, al);
				break;
			case 2: t = new Timer(10, al);
				break;
			case 3: t = new Timer(1, al);
				break;
			default: t = new Timer(1000, al);
				break;
		}
	}

	ActionListener al = new ActionListener(){
		public void actionPerformed(ActionEvent e){
			finishTime++;
		}
	};

	public synchronized void start(){
		if(!isStarted){
			isStarted = true;
			startTime = finishTime;
			t.start();
		}
	}

	public synchronized void finish(){
		if(isStarted){
			isStarted = false;
			t.stop();
		}
	}

	public synchronized long getTimeElapsed(){
		return finishTime - startTime;
	}

	public synchronized long getCurrentStart(){
		return startTime;
	}

	public synchronized long getCurrentFinish(){
		return finishTime;
	}

	public synchronized void resetTimer(){
		if(!isStarted){
			startTime = 0;
			finishTime = 0;
		}else JOptionPane.showMessageDialog(null, "Please stop the clock before trying to reset it.");
	}
}

public class DriverProgram_3{

	public static void main(String... args){
		Clock c = new Clock(Clock.SECONDS);
		c.start();
		lengthyMethod();
		c.finish();
		System.out.println("Nethod lengthyMethod took " + c.getTimeElapsed() + " seconds to finish execution.");
	}

	public static void lengthyMethod(){
		for(long i = 0; i < 1000000000; i++);
	}
}

Was my approach wrong?

[VernonDozier]

I believe that the problem is that there is some overhead when calling that action listener when the timer fires. It seems to me, at least on my computer, that every time the timer fired, 25 milliseconds elapsed that was not timed. My guess, and it's only a guess, is that the timer does NOT automatically restart its clock when the timer fires. Rather the clock starts again AFTER the ActionListener is finished. Only when all of the work of the ActionListener is done does the clock restart, so you're losing 25 milliseconds each time, which is a long time compared to a one millisecond timer. That appears to be why the milliseconds were so off, centiseconds were way off, but not as bad as the milliseconds, etc. How off you are in the time depends on the ratio of the time per timer cycle to the time spent in the action listener.

To further confirm the point, I added a pause (arithmetic calculations to eat up time, currently commented out but you can uncomment and change the numbers to experiment) to the action listener to see whether that reduced the number of clock cycles. It does. I've been getting some accurate and inaccurate results, so the pause time is possibly a little more complicated than just a 25 millisecond pause each clock tick. However the pattern seems to hold. Either that timer is not starting a new cycle right when it fires due to going through the action listener or some other overhead factors. I've never used timers too much, so I don't particularly know the solution, but play with the numbers for the clock cycle, the action listener pause, etc., and you'll notice they make a big difference. Here's the code I used. Like I said, sometimes it's accurate, sometimes not so much, but the trend is constant. This last run had perfect timing, so I'll end here and pretend it always works as well. ;)

import javax.swing.*;
import java.awt.event.*;


public class Clock
{    
    private Timer t;
    private long startTime = 0, finishTime = 0;
    private boolean isStarted = false;
    public static final int SECONDS = 0, DECASECONDS = 1, CENTISECONDS = 2, MILLISECONDS = 3;
    
    public Clock(int numMilli)
    {   
        t = new Timer(numMilli, al);
    }

    
    
    ActionListener al = new ActionListener()
    {
        public void actionPerformed(ActionEvent e)
        {
/*            for (int i = 0;i < 2000; i++)
            {
                for (int j = 0; j < 2000; j++)
                {
                    int k = i * j;
                }
            }*/
            
            finishTime++;
        }
    };
    
    

    
    public synchronized void start()
    {
        if(!isStarted)
        {
            isStarted = true;
            startTime = finishTime;
            t.start();
        }
    }
    
    public synchronized void finish()
    {
        if(isStarted)
        {
            isStarted = false;
            t.stop();
        }
    }
    
    public synchronized long getNumCycles()
    {
        return finishTime - startTime;
    }
    
    public synchronized long getCurrentStart()
    {
        return startTime;
    }
    
    public synchronized long getCurrentFinish()
    {
        return finishTime;
    }
    
    public synchronized void resetTimer()
    {
        if(!isStarted)
        {
            startTime = 0;
            finishTime = 0;
        }
        else JOptionPane.showMessageDialog(null, "Please stop the clock before trying to reset it.");
    }
}

public class DriverProgram_3
{
    
    public static void main(String... args)
    {
        int numMilliPerClock = 300;
        Clock c = new Clock(numMilliPerClock);
        c.start();
        lengthyMethod();
        c.finish();
        long numClockCycles = c.getNumCycles();
        System.out.println ("Number of clock cycles =" + numClockCycles);
        
        double clockTime =  c.getNumCycles() * numMilliPerClock / 1000.0;
        System.out.println("Clock time = " + clockTime);
                
        double totalTimeDelay = 0.025 * numClockCycles;
        System.out.println("Time delay = " + totalTimeDelay);
        
        double totalRunTime = clockTime + totalTimeDelay;
        
        System.out.println("Program run-time = " + totalRunTime);
    }
    
    public static void lengthyMethod()
    {
        for(long i = 0; i < 500000; i++)
        {
            for (long k = 0; k < 50000; k++)
            {
                long j = i * k;
            }                        
        }
    }
}

[Ezzaral]

I really wouldn't recommend trying to keep accurate time information by incrementing your own variables, since you have little control over things like processor time-slicing and garbage collection. This portion here presents an additional unknown

ActionListener al = new ActionListener(){
		public void actionPerformed(ActionEvent e){
			finishTime++;
		}
	};

That listener code will execute on the AWT event dispatching thread, in a single-threaded queue with all of the other AWT events. You have no way of knowing exactly when actionPerformed() will get executed.

If you need accurate timing use System.nanoTime() in conjuction with variables to capture the time at crucial points and make timing decisions based on a calculated elapsed time against the current value of System.nanoTime().

[Alex Edwards]

Thank you both.

I'll make some changes such that I wont be relying on the EDT but instead the actual time elapsed provided by the System.

[Ezzaral]

The Swing Timer is great for a lot of things. It just depends on your expectations of precision. The piece to keep in mind with them is this part from the api doc

Although all Timers perform their waiting using a single, shared thread (created by the first Timer object that executes), the action event handlers for Timers execute on another thread -- the event-dispatching thread. This means that the action handlers for Timers can safely perform operations on Swing components. However, it also means that the handlers must execute quickly to keep the GUI responsive.

If a handful of milliseconds or even a half-second perhaps don't have much impact on the operation you are performing, say like updating a GUI text field or repainting a graph or some such, the thread timing is of no real consequence. If more accurate timing is needed, or in your case constant accumulation of a time value over many firings of the timer, then the uncertainty in execution time can become a concern.

[Alex Edwards]

Made some changes - works perfectly now.

import java.util.concurrent .*;
import javax.swing.JOptionPane;

public class Clock{

	private ExecutorService es;
	private long startTime = 0, finishTime = 0, decided;
	private boolean isStarted = false;
	public static final int SECONDS = 1000000000, DECASECONDS = 100000000, CENTISECONDS = 10000000, MILLISECONDS = 1000000;

	public Clock(int timeType){
		es = Executors.newFixedThreadPool(1);
		switch(timeType){
			case SECONDS: decided = SECONDS;
				break;
			case DECASECONDS: decided = DECASECONDS;
				break;
			case CENTISECONDS: decided = CENTISECONDS;
				break;
			case MILLISECONDS: decided = MILLISECONDS;
				break;
			default: decided = SECONDS;
				break;
		}
	}

	Runnable rn = new Runnable(){
		public void run(){ while(true){ if(isStarted)finishTime = (System.nanoTime()/decided); } }
	};

	public synchronized void start(){
		if(!isStarted){
			isStarted = true;
			startTime = (System.nanoTime()/decided);
			es.execute(rn);
		}else JOptionPane.showMessageDialog(null, "The clock has already started.");
	}

	public synchronized void stop(){
		if(isStarted){
			isStarted = false;
		}else JOptionPane.showMessageDialog(null, "The clock has already been stopped.");
	}

	@Override
	protected void finalize() throws Throwable{
		try{
			isStarted = false;
		}finally{
			es.shutdown();
			super.finalize();
		}
	}

	public synchronized long getTimeElapsed(){
		return finishTime - startTime;
	}

	public synchronized long getCurrentStart(){
		return startTime;
	}

	public synchronized long getCurrentFinish(){
		return finishTime;
	}

	public synchronized void resetTimer(){
		if(!isStarted){
			startTime = 0;
			finishTime = 0;
		}else JOptionPane.showMessageDialog(null, "Please stop the clock before trying to reset it.");
	}
}

public class DriverProgram_3{

	public static void main(String... args){
		Clock c = new Clock(Clock.SECONDS);
		c.start();
		lengthyMethod();
		c.stop();
		System.out.println("Nethod lengthyMethod took " + c.getTimeElapsed() + " seconds to finish execution.");
		c.start();
		lengthyMethod();
		c.stop();
		System.out.println(c.getTimeElapsed());
	}

	public static void lengthyMethod(){
		for(long i = 0; i < 1000000000; i++);
	}
}