Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]


Groups > comp.lang.java.programmer > #35408 > unrolled thread

Logging database statement duration in a DRY way

Started byCecil Westerhof <Cecil@decebal.nl>
First post2016-08-19 14:32 +0200
Last post2016-08-19 22:34 +0100
Articles 10 — 6 participants

Back to article view | Back to comp.lang.java.programmer


Contents

  Logging database statement duration in a DRY way Cecil Westerhof <Cecil@decebal.nl> - 2016-08-19 14:32 +0200
    Re: Logging database statement duration in a DRY way Eric Sosman <esosman@comcast-dot-net.invalid> - 2016-08-19 09:05 -0400
      Re: Logging database statement duration in a DRY way Cecil Westerhof <Cecil@decebal.nl> - 2016-08-19 20:54 +0200
    Re: Logging database statement duration in a DRY way Cecil Westerhof <Cecil@decebal.nl> - 2016-08-19 15:12 +0200
      Re: Logging database statement duration in a DRY way Eric Sosman <esosman@comcast-dot-net.invalid> - 2016-08-19 10:01 -0400
      Re: Logging database statement duration in a DRY way Arne Vajhøj <arne@vajhoej.dk> - 2016-08-19 22:17 -0400
        Re: Logging database statement duration in a DRY way Arne Vajhøj <arne@vajhoej.dk> - 2016-08-19 22:37 -0400
    Re: Logging database statement duration in a DRY way Martin Gregorie <martin@address-in-sig.invalid> - 2016-08-19 16:05 +0000
      Re: Logging database statement duration in a DRY way Eric Douglas <e.d.programmer@gmail.com> - 2016-08-19 10:06 -0700
    Re: Logging database statement duration in a DRY way Steven Simpson <ss@my.domain.invalid> - 2016-08-19 22:34 +0100

#35408 — Logging database statement duration in a DRY way

FromCecil Westerhof <Cecil@decebal.nl>
Date2016-08-19 14:32 +0200
SubjectLogging database statement duration in a DRY way
Message-ID<87wpjdhrbm.fsf@Equus.decebal.nl>
I like to log the time it takes for certain database actions. At the
moment I do this like this:
    startTime = System.nanoTime();
    ps = conn.prepareStatement(insertLine);
    ps.setString(1, className);
    ps.setLong(  2, pid);
    ps.setLong(  3, free);
    ps.setLong(  4, rt.maxMemory() / divideValue);
    ps.setLong(  5, total);
    ps.executeUpdate();
    ps.close();
    stopTime = System.nanoTime();
    logMessage(String.format("preparedStatement saveMemoryLineNoGC took %f milliseconds",
                             (stopTime - startTime) * 1E-6));

This works, but I need to copy the first and last two statements and
edit the last one, so I was wondering if this could be done more DRY
(Do not Repeat Yourself). In C(++) you would use a macro, but as far
as I know this is not possible with Java.

-- 
Cecil Westerhof
Senior Software Engineer
LinkedIn: http://www.linkedin.com/in/cecilwesterhof

[toc] | [next] | [standalone]


#35410

FromEric Sosman <esosman@comcast-dot-net.invalid>
Date2016-08-19 09:05 -0400
Message-ID<np7083$rmt$1@dont-email.me>
In reply to#35408
On 8/19/2016 8:32 AM, Cecil Westerhof wrote:
> I like to log the time it takes for certain database actions. At the
> moment I do this like this:
>     startTime = System.nanoTime();
>     ps = conn.prepareStatement(insertLine);
>     ps.setString(1, className);
>     ps.setLong(  2, pid);
>     ps.setLong(  3, free);
>     ps.setLong(  4, rt.maxMemory() / divideValue);
>     ps.setLong(  5, total);
>     ps.executeUpdate();
>     ps.close();
>     stopTime = System.nanoTime();
>     logMessage(String.format("preparedStatement saveMemoryLineNoGC took %f milliseconds",
>                              (stopTime - startTime) * 1E-6));
>
> This works, but I need to copy the first and last two statements and
> edit the last one, so I was wondering if this could be done more DRY
> (Do not Repeat Yourself). In C(++) you would use a macro, but as far
> as I know this is not possible with Java.

     I suppose you could put the "guts" in an instance implementing a
suitable interface and hand the instance to a time-it-and-log-it
method.  You might end up with something like

	static void timeAndLog(String label, Runnable thing) {
	    long startTime = System.nanoTime();
	    thing.run();
	    long stopTime = System.nanoTime();
	    logMessage(String.format("%s took %f milliseconds",
	        (stopTime - startTime) * 1E-6);
	}

	// ...

	timeAndLog("preparedStatement saveMemoryLineNoGC", () -> {
	    ps = conn.prepareStatement(insertLine);
	    // ...
	    ps.close();
	});

Only you can judge whether this is worth while.

-- 
esosman@comcast-dot-net.invalid
The Tooth Fairy has gone high-tech, now pays in Bitecoin.

[toc] | [prev] | [next] | [standalone]


#35418

FromCecil Westerhof <Cecil@decebal.nl>
Date2016-08-19 20:54 +0200
Message-ID<87lgzsio7e.fsf@Equus.decebal.nl>
In reply to#35410
On Friday 19 Aug 2016 15:05 CEST, Eric Sosman wrote:

> On 8/19/2016 8:32 AM, Cecil Westerhof wrote:
>> I like to log the time it takes for certain database actions. At
>> the moment I do this like this: startTime = System.nanoTime(); ps =
>> conn.prepareStatement(insertLine); ps.setString(1, className);
>> ps.setLong( 2, pid); ps.setLong( 3, free); ps.setLong( 4,
>> rt.maxMemory() / divideValue); ps.setLong( 5, total);
>> ps.executeUpdate(); ps.close(); stopTime = System.nanoTime();
>> logMessage(String.format("preparedStatement saveMemoryLineNoGC took
>> %f milliseconds", (stopTime - startTime) * 1E-6));
>>
>> This works, but I need to copy the first and last two statements
>> and edit the last one, so I was wondering if this could be done
>> more DRY (Do not Repeat Yourself). In C(++) you would use a macro,
>> but as far as I know this is not possible with Java.
>
> I suppose you could put the "guts" in an instance implementing a
> suitable interface and hand the instance to a time-it-and-log-it
> method.  You might end up with something like
>
> 	static void timeAndLog(String label, Runnable thing) {
> 	    long startTime = System.nanoTime();
> 	    thing.run();
> 	    long stopTime = System.nanoTime();
> 	    logMessage(String.format("%s took %f milliseconds",
> 	        (stopTime - startTime) * 1E-6);
> 	}
>
> 	// ...
>
> 	timeAndLog("preparedStatement saveMemoryLineNoGC", () -> {
> 	    ps = conn.prepareStatement(insertLine);
> 	    // ...
> 	    ps.close();
> 	});
>
> Only you can judge whether this is worth while.

I already found a solution. (See my reply on my own post.) For the
moment that is good enough, but I will keep your solution in mind.

-- 
Cecil Westerhof
Senior Software Engineer
LinkedIn: http://www.linkedin.com/in/cecilwesterhof

[toc] | [prev] | [next] | [standalone]


#35411

FromCecil Westerhof <Cecil@decebal.nl>
Date2016-08-19 15:12 +0200
Message-ID<87pop4j41i.fsf@Equus.decebal.nl>
In reply to#35408
On Friday 19 Aug 2016 14:32 CEST, Cecil Westerhof wrote:

> I like to log the time it takes for certain database actions. At the
> moment I do this like this: startTime = System.nanoTime(); ps =
> conn.prepareStatement(insertLine); ps.setString(1, className);
> ps.setLong( 2, pid); ps.setLong( 3, free); ps.setLong( 4,
> rt.maxMemory() / divideValue); ps.setLong( 5, total);
> ps.executeUpdate(); ps.close(); stopTime = System.nanoTime();
> logMessage(String.format("preparedStatement saveMemoryLineNoGC took
> %f milliseconds", (stopTime - startTime) * 1E-6));
>
> This works, but I need to copy the first and last two statements and
> edit the last one, so I was wondering if this could be done more DRY
> (Do not Repeat Yourself). In C(++) you would use a macro, but as far
> as I know this is not possible with Java.

For this simple case I found a solution. The only part that really can
change is the last part, so I now have:
    startTime = System.nanoTime();
    ps        = conn.prepareStatement(insertLine);
    ps.setString(1, className);
    ps.setLong(  2, pid);
    ps.setLong(  3, free);
    ps.setLong(  4, rt.maxMemory() / divideValue);
    ps.setLong(  5, total);
    ps.executeUpdate();
    ps.close();
    stopTime = System.nanoTime();
    logDatabaseAction("preparedStatement saveMemoryLineNoGC", stopTime - startTime);

And logDatabaseAction is:
    private static void logDatabaseAction(String message, long duration) {
        logMessage(String.format("%-40s took %e milliseconds",
                                 message,
                                 duration * 1E-6));
     }

I like to have the times outlined under each-other. When there comes a
longer string I just have to change the -40. I also changed from %e to
%f to have a better (in my opinion) display of the times. Probably I
should change %f to %.2f.

The output:
14:55:47: preparedStatement freeMemoryThread       took 1.366532e+02 milliseconds
14:56:48: preparedStatement saveMemoryLine         took 1.603480e+02 milliseconds

-- 
Cecil Westerhof
Senior Software Engineer
LinkedIn: http://www.linkedin.com/in/cecilwesterhof

[toc] | [prev] | [next] | [standalone]


#35412

FromEric Sosman <esosman@comcast-dot-net.invalid>
Date2016-08-19 10:01 -0400
Message-ID<np73ge$72h$1@dont-email.me>
In reply to#35411
On 8/19/2016 9:12 AM, Cecil Westerhof wrote:
> On Friday 19 Aug 2016 14:32 CEST, Cecil Westerhof wrote:
>[...]
> For this simple case I found a solution. The only part that really can
> change is the last part, so I now have:
>     startTime = System.nanoTime();
>     ps        = conn.prepareStatement(insertLine);
>     ps.setString(1, className);
>     ps.setLong(  2, pid);
>     ps.setLong(  3, free);
>     ps.setLong(  4, rt.maxMemory() / divideValue);
>     ps.setLong(  5, total);
>     ps.executeUpdate();
>     ps.close();
>     stopTime = System.nanoTime();
>     logDatabaseAction("preparedStatement saveMemoryLineNoGC", stopTime - startTime);
>
> And logDatabaseAction is:
>     private static void logDatabaseAction(String message, long duration) {
>         logMessage(String.format("%-40s took %e milliseconds",
>                                  message,
>                                  duration * 1E-6));
>      }
>
> I like to have the times outlined under each-other. When there comes a
> longer string I just have to change the -40. I also changed from %e to
> %f to have a better (in my opinion) display of the times. Probably I
> should change %f to %.2f.

     You could achieve a further tiny abbreviation by passing startTime
into the logging function and letting it call nanoTime() internally.
(Someone may say "That would pollute the timing!" but since you're only
planning to report 10-microsecond units that seems irrelevant.)

> The output:
> 14:55:47: preparedStatement freeMemoryThread       took 1.366532e+02 milliseconds
> 14:56:48: preparedStatement saveMemoryLine         took 1.603480e+02 milliseconds

     Some further avoidance of formatting worries could be attained
by rearranging the output a bit, if that's permissible:

	14:55:47: 136.65 ms for preparedStatement freeMemoryThread
	14:56:48: 160.35 ms for preparedStatement saveMemoryLine

... so you stop fretting about "%-40s" and just use "%s".

-- 
esosman@comcast-dot-net.invalid
The Tooth Fairy has gone high-tech, now pays in Bitecoin.

[toc] | [prev] | [next] | [standalone]


#35422

FromArne Vajhøj <arne@vajhoej.dk>
Date2016-08-19 22:17 -0400
Message-ID<np8ejr$kaa$1@gioia.aioe.org>
In reply to#35411
On 8/19/2016 9:12 AM, Cecil Westerhof wrote:
> For this simple case I found a solution. The only part that really can
> change is the last part, so I now have:
>     startTime = System.nanoTime();
>     ps        = conn.prepareStatement(insertLine);
>     ps.setString(1, className);
>     ps.setLong(  2, pid);
>     ps.setLong(  3, free);
>     ps.setLong(  4, rt.maxMemory() / divideValue);
>     ps.setLong(  5, total);
>     ps.executeUpdate();
>     ps.close();
>     stopTime = System.nanoTime();
>     logDatabaseAction("preparedStatement saveMemoryLineNoGC", stopTime - startTime);
>
> And logDatabaseAction is:
>     private static void logDatabaseAction(String message, long duration) {
>         logMessage(String.format("%-40s took %e milliseconds",
>                                  message,
>                                  duration * 1E-6));
>      }

That is not a bad approach.

Probably the approach that you should go with.

But just in case you are interested in alternatives here a two ideas.

First some un timed code:

package timerfun;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;
import java.sql.ResultSet;

public class Base {
     public static void main(String[] args) throws Exception {
         try(Connection con = 
DriverManager.getConnection("jdbc:mysql://localhost/Test", "root", "")) {
             try(PreparedStatement pstmt = con.prepareCall("SELECT f1,f2 
FROM t1")) {
                 try(ResultSet rs = pstmt.executeQuery()) {
                     while(rs.next()) {
                         int f1 = rs.getInt("f1");
                         String f2 = rs.getString("f2");
                         System.out.printf("%d %s\n", f1, f2);
                     }
                 }
             }
         }
     }
}

Now the same code timed approx. the same way that you do:

package timerfun;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;
import java.sql.ResultSet;

public class BaseTimed {
     public static void main(String[] args) throws Exception {
         try(Connection con = 
DriverManager.getConnection("jdbc:mysql://localhost/Test", "root", "")) {
             long t1 = System.nanoTime();
             try(PreparedStatement pstmt = con.prepareCall("SELECT f1,f2 
FROM t1")) {
                 try(ResultSet rs = pstmt.executeQuery()) {
                     while(rs.next()) {
                         int f1 = rs.getInt("f1");
                         String f2 = rs.getString("f2");
                         System.out.printf("%d %s\n", f1, f2);
                     }
                 }
             }
             long t2 = System.nanoTime();
             System.out.printf("%s : %d\n", "main", t2 - t1);
         }
     }
}

And as I said then that is probably just fine.

But in case you want to decrease the amount of timing code each place,
then you could use a code block time measuring method.

Example:

package timerfun;

public class Timer {
     @FunctionalInterface
     public static interface CodeBlock {
         public void execute() throws Exception;
     }
     public static void time(String name, CodeBlock cb) throws Exception {
         long t1 = System.nanoTime();
         cb.execute();
         long t2 = System.nanoTime();
         System.out.printf("%s : %d\n", name, t2 - t1);
     }
}

And now the timed code looks like:

package timerfun;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;
import java.sql.ResultSet;

import static timerfun.Timer.time;

public class Timed {
     public static void main(String[] args) throws Exception {
         try(Connection con = 
DriverManager.getConnection("jdbc:mysql://localhost/Test", "root", "")) {
             time("demo", () -> {
                 try(PreparedStatement pstmt = con.prepareCall("SELECT 
f1,f2 FROM t1")) {
                     try(ResultSet rs = pstmt.executeQuery()) {
                         while(rs.next()) {
                             int f1 = rs.getInt("f1");
                             String f2 = rs.getString("f2");
                             System.out.printf("%d %s\n", f1, f2);
                         }
                     }
                 }
             });
         }
     }
}

Just a method name and the context string. I think that is as short
as it is possible in pure Java.

But if we go outside of pure Java, then this is a text book case
for AOP!

We can do it with AspectJ without even touching the Java code.

package timerfun;

import java.util.Map;
import java.util.concurrent.ConcurrentHashMap;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;

@Aspect
public class TimerAspect {
     private static Map<String,Long> store = new 
ConcurrentHashMap<String,Long>();
     @Pointcut("call(* java.sql.Connection.prepareCall(*)) && 
!within(TimerAspect)")
     public void start(ProceedingJoinPoint pjp, 
JoinPoint.EnclosingStaticPart esp) {}
     @Pointcut("call(* java.sql.PreparedStatement.close()) && 
!within(TimerAspect)")
     public void end(ProceedingJoinPoint pjp, 
JoinPoint.EnclosingStaticPart esp) {}
     @Around(value = "start(pjp, esp)")
     public Object startAround(ProceedingJoinPoint pjp, 
JoinPoint.EnclosingStaticPart esp) throws Throwable {
         String loc = esp.getSignature().toString();
         long t1 = System.nanoTime();
         store.put(loc, t1);
         Object res = pjp.proceed();
         return res;
     }
     @Around(value = "end(pjp, esp)")
     public Object endAround(ProceedingJoinPoint pjp, 
JoinPoint.EnclosingStaticPart esp) throws Throwable {
         Object res = pjp.proceed();
         long t2 = System.nanoTime();
         String loc = esp.getSignature().toString();
         long t1 = store.remove(loc);
         System.out.printf("%s : %d\n", loc, t2 - t1);
         return res;
     }
}

Arne



[toc] | [prev] | [next] | [standalone]


#35423

FromArne Vajhøj <arne@vajhoej.dk>
Date2016-08-19 22:37 -0400
Message-ID<np8fot$lea$1@gioia.aioe.org>
In reply to#35422
On 8/19/2016 10:17 PM, Arne Vajhøj wrote:
> import java.util.Map;
> import java.util.concurrent.ConcurrentHashMap;
>
> import org.aspectj.lang.JoinPoint;
> import org.aspectj.lang.ProceedingJoinPoint;
> import org.aspectj.lang.annotation.Around;
> import org.aspectj.lang.annotation.Aspect;
> import org.aspectj.lang.annotation.Pointcut;
>
> @Aspect
> public class TimerAspect {
>     private static Map<String,Long> store = new
> ConcurrentHashMap<String,Long>();
>     @Pointcut("call(* java.sql.Connection.prepareCall(*)) &&
> !within(TimerAspect)")
>     public void start(ProceedingJoinPoint pjp,
> JoinPoint.EnclosingStaticPart esp) {}
>     @Pointcut("call(* java.sql.PreparedStatement.close()) &&
> !within(TimerAspect)")
>     public void end(ProceedingJoinPoint pjp,
> JoinPoint.EnclosingStaticPart esp) {}
>     @Around(value = "start(pjp, esp)")
>     public Object startAround(ProceedingJoinPoint pjp,
> JoinPoint.EnclosingStaticPart esp) throws Throwable {
>         String loc = esp.getSignature().toString();
>         long t1 = System.nanoTime();
>         store.put(loc, t1);
>         Object res = pjp.proceed();
>         return res;
>     }
>     @Around(value = "end(pjp, esp)")
>     public Object endAround(ProceedingJoinPoint pjp,
> JoinPoint.EnclosingStaticPart esp) throws Throwable {
>         Object res = pjp.proceed();
>         long t2 = System.nanoTime();
>         String loc = esp.getSignature().toString();
>         long t1 = store.remove(loc);
>         System.out.printf("%s : %d\n", loc, t2 - t1);
>         return res;
>     }
> }

Make that:

import java.util.Map;
import java.util.concurrent.ConcurrentHashMap;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;

@Aspect
public class TimerAspect {
     private static Map<String,Long> store = new 
ConcurrentHashMap<String,Long>();
     @Pointcut("call(* java.sql.Connection.prepareCall(*)) && 
!within(TimerAspect)")
     public void start(ProceedingJoinPoint pjp, 
JoinPoint.EnclosingStaticPart esp) {}
     @Pointcut("call(* java.sql.PreparedStatement.close()) && 
!within(TimerAspect)")
     public void end(ProceedingJoinPoint pjp, 
JoinPoint.EnclosingStaticPart esp) {}
     @Around(value = "start(pjp, esp)")
     public Object startAround(ProceedingJoinPoint pjp, 
JoinPoint.EnclosingStaticPart esp) throws Throwable {
         long t1 = System.nanoTime();
         Object res = pjp.proceed();
         store.put(res.toString(), t1);
         return res;
     }
     @Around(value = "end(pjp, esp)")
     public Object endAround(ProceedingJoinPoint pjp, 
JoinPoint.EnclosingStaticPart esp) throws Throwable {
         long t1 = store.remove(pjp.getTarget().toString().toString());
         Object res = pjp.proceed();
         long t2 = System.nanoTime();
         String loc = esp.getSignature().toString();
         System.out.printf("%s : %d\n", loc, t2 - t1);
         return res;
     }
}

It is better at handling multiple PreparedStatements in same method.

Arne

[toc] | [prev] | [next] | [standalone]


#35413

FromMartin Gregorie <martin@address-in-sig.invalid>
Date2016-08-19 16:05 +0000
Message-ID<np7ap5$sqd$1@dont-email.me>
In reply to#35408
On Fri, 19 Aug 2016 14:32:45 +0200, Cecil Westerhof wrote:

> I like to log the time it takes for certain database actions.

You could write a StopWatch class with start() and stop() methods:
start() would grab the current time and stop() would return the amount of 
time since start() was called as milliseconds or nanoseconds. Different 
instances can be used to time various parts of an application. It would 
be trivial to put it under the control of a multi-level debug class or 
classes so that timing measurements are only made at appropriate debug 
levels.
 

-- 
martin@   | Martin Gregorie
gregorie. | Essex, UK
org       |

[toc] | [prev] | [next] | [standalone]


#35414

FromEric Douglas <e.d.programmer@gmail.com>
Date2016-08-19 10:06 -0700
Message-ID<0fb3031a-9cb3-46c7-8d8d-5c2cf25416ea@googlegroups.com>
In reply to#35413
On Friday, August 19, 2016 at 12:06:09 PM UTC-4, Martin Gregorie wrote:
> You could write a StopWatch class with start() and stop() methods:

Someone already did.  I made a copy.


import java.text.SimpleDateFormat;
import java.util.Calendar;  

/**
 * @author Carlos Quintanilla
 */

public class StopWatch {
    // constants
    private final long nsPerTick = 100;
    private final long nsPerMs = 1000000;
    private final long nsPerSs = 1000000000;
    private final long nsPerMm = 60000000000L;
    private final long nsPerHh = 3600000000000L;

    private long startTime = 0;
    private long stopTime = 0;
    private boolean running = false;
    
    /**
     * Starts measuring elapsed time
     * for an interval.
     */
    public void start() {
        this.startTime = System.nanoTime();       
        this.running = true;
    }
    
    /**
     * Stops measuring elapsed time
     * for an interval.
     */
    public void stop() {
        this.stopTime = System.nanoTime();
        this.running = false;
    }
    
    /**
     * Stops time interval measurement 
     * and resets the elapsed time to zero.
     */ 
    public void reset() {
        this.startTime = 0;
        this.stopTime = 0;
        this.running = false;
    }
    
    /**
     * Gets the total elapsed time measured 
     * by the current instance, in nanoseconds.
     * 1 Tick = 100 nanoseconds 
     * @return number of ticks 
     */
    public long getElapsedTicks() {
        long elapsed;
        if (running) {
             elapsed = (System.nanoTime() - startTime);
        }
        else {
            elapsed = (stopTime - startTime);
        }
        return elapsed / nsPerTick;
    }
    
    /**
     * Gets the total elapsed time measured 
     * by the current instance, in milliseconds.
     * 10000 Ticks = 1 millisecond (1000000 nanoseconds)
     * @return number of millis 
     */
    public long getElapsedMilliseconds() {
        long elapsed;
        if (running) {
             elapsed = (System.nanoTime() - startTime);
        }
        else {
            elapsed = (stopTime - startTime);
        }
        return elapsed / nsPerMs;
    }
    
    /**
     * Gets the total elapsed time measured 
     * by the current instance, in seconds.
     * 10000000 Ticks = 1 second (1000 milliseconds)
     * @return number of secs 
     */
    public long getElapsedSeconds() {
        long elapsed;
        if (running) {
             elapsed = (System.nanoTime() - startTime);
        }
        else {
            elapsed = (stopTime - startTime);
        }        
        return elapsed / nsPerSs;
    }
    
    /**
     * Gets the total elapsed time measured 
     * by the current instance, in minutes.
     * 600000000 Ticks = 1 minute (60 seconds)
     * @return number of mins 
     */
    public long getElapsedMinutes() {
        long elapsed;
        if (running) {
             elapsed = (System.nanoTime() - startTime);
        }
        else {
            elapsed = (stopTime - startTime);
        }        
        return elapsed / nsPerMm;
    }
    
    /**
     * Gets the total elapsed time measured 
     * by the current instance, in hours.
     * 36000000000 Ticks = 1 hour (60 minutes)
     * @return number of hrs 
     */
    public long getElapsedHours() {
        long elapsed;
        if (running) {
             elapsed = (System.nanoTime() - startTime);
        }
        else {
            elapsed = (stopTime - startTime);
        }        
        return elapsed / nsPerHh;
    }
    
    /**
     * Gets the total elapsed time with format 
     * 00:00:00.0000000 = 00:mm:ss.SSS + 9999 Ticks
     * @return formatted time string 
     */ 
    public String getElapsed() {
        String timeFormatted = "";
        timeFormatted = this.formatTime(this.getElapsedTicks());        
        return timeFormatted;
    }
    
    /**
     * Gets the total elapsed time with format 
     * 00:00:00.0000000 = 00:mm:ss.SSS + #### Ticks
     * @param elapsedTicks elapsed ticks between start and stop nano time
     */ 
    private String formatTime(final long elapsedTicks) {        
        String formattedTime = "";
        // should be hh:mm:ss.SSS, but 00 starts with 01 
        SimpleDateFormat formatter = new SimpleDateFormat("00:mm:ss.SSS");
        Calendar calendar = Calendar.getInstance();        
        
        if (elapsedTicks <= 9999) {
            calendar.setTimeInMillis(0);
            formattedTime = formatter.format(calendar.getTime()) 
                    + String.valueOf(String.format("%04d", elapsedTicks));
        }
        else {
            calendar.setTimeInMillis(elapsedTicks * nsPerTick / nsPerMs);            
            String formattedTicks = String.format("%07d", elapsedTicks);
            formattedTicks = formattedTicks.substring(formattedTicks.length() - 4);
            formattedTime = formatter.format(calendar.getTime()) + formattedTicks;
        }
        return formattedTime;
    }
}

[toc] | [prev] | [next] | [standalone]


#35419

FromSteven Simpson <ss@my.domain.invalid>
Date2016-08-19 22:34 +0100
Message-ID<7kak8d-rai.ln1@s.simpson148.btinternet.com>
In reply to#35408
On 19/08/16 13:32, Cecil Westerhof wrote:
> This works, but I need to copy the first and last two statements and
> edit the last one, so I was wondering if this could be done more DRY
> (Do not Repeat Yourself). In C(++) you would use a macro, but as far
> as I know this is not possible with Java.

You could create a class implementing AutoCloseable:

try (MyTimer t = new MyTimer(logger, "preparedStatement saveMemoryLineNoGC")) {
   ...
}


-- 
ss at comp dot lancs dot ac dot uk

[toc] | [prev] | [standalone]


Back to top | Article view | comp.lang.java.programmer


csiph-web