Path: csiph.com!eternal-september.org!feeder.eternal-september.org!news.eternal-september.org!.POSTED!not-for-mail
From: Eric Sosman <esosman@comcast-dot-net.invalid>
Newsgroups: comp.lang.java.programmer
Subject: Re: Logging database statement duration in a DRY way
Date: Fri, 19 Aug 2016 10:01:36 -0400
Organization: A noiseless patient Spider
Lines: 49
Message-ID: <np73ge$72h$1@dont-email.me>
References: <87wpjdhrbm.fsf@Equus.decebal.nl> <87pop4j41i.fsf@Equus.decebal.nl>
Mime-Version: 1.0
Content-Type: text/plain; charset=windows-1252; format=flowed
Content-Transfer-Encoding: 7bit
Injection-Date: Fri, 19 Aug 2016 14:01:50 -0000 (UTC)
Injection-Info: mx02.eternal-september.org; posting-host="22e5ab429c5a4bb738666b9c52e40d69"; logging-data="7249"; mail-complaints-to="abuse@eternal-september.org";	posting-account="U2FsdGVkX1+fuugigyA3+g/1qTwKVc8Q"
User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:45.0) Gecko/20100101 Thunderbird/45.2.0
In-Reply-To: <87pop4j41i.fsf@Equus.decebal.nl>
Cancel-Lock: sha1:Rw2D+sj91L2tCBT4Kd/4d42qJEE=
Xref: csiph.com comp.lang.java.programmer:35412

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.