Path: csiph.com!eternal-september.org!feeder.eternal-september.org!news.eternal-september.org!.POSTED!not-for-mail
From: Cecil Westerhof <Cecil@decebal.nl>
Newsgroups: comp.lang.java.programmer
Subject: Re: Logging database statement duration in a DRY way
Date: Fri, 19 Aug 2016 15:12:41 +0200
Organization: Decebal Computing
Lines: 50
Message-ID: <87pop4j41i.fsf@Equus.decebal.nl>
References: <87wpjdhrbm.fsf@Equus.decebal.nl>
Mime-Version: 1.0
Content-Type: text/plain
Injection-Info: mx02.eternal-september.org; posting-host="12baf5125b19322b899c79c2e3878015"; logging-data="29942"; mail-complaints-to="abuse@eternal-september.org";	posting-account="U2FsdGVkX1/jiYxvE222kO+oGRVjG2T5jClte2Cq3po="
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/24.3 (gnu/linux)
X-Homepage: http://www.decebal.nl/
Cancel-Lock: sha1:N0qgpvQ8z+3IWw/G/jC77C7q/K0= sha1:ffhc4ki5A4Rcc1e+3UJT6a6/+dA=
Xref: csiph.com comp.lang.java.programmer:35411

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