It seems I have problems with my connection pool tool. There is a big delay when it obtains the DB connection.
What I try to achieve is to get all the cases from log file when this incident occurs.

The related log entries look like

2018-03-12 16:18:44,070 efault task-166 gine.jdbc.internal.LogicalConnectionImpl DEBUG Obtaining JDBC connection
2018-03-12 16:20:23,172 efault task-166 gine.jdbc.internal.LogicalConnectionImpl DEBUG Obtained JDBC connection

So if the pattern 'DEBUG Obtaining JDBC connection' occurs then extract the date '2018-03-12 16:18:44,070' and when the pattern 'DEBUG Obtained JDBC connection' is found then extract its date and compare the 2 dates. If the difference is more than 2 sec then log then.

I know it is pretty complicated to solve it with one line of code but is it possible without writing a program to do that?

  • what does mean "then log then" exactly? – RomanPerekhrest May 16 '18 at 8:44
  • Do the ,070 and ,172 represent milliseconds, and do you care about them? If "obtaining" happens at 16:18:44,999 and "obtained" happens at 16:18:46,001 (a difference of 1.002 seconds, yet apparently 2 seconds if you drop the milliseconds), do you want that reported? – Jeff Schaller May 16 '18 at 12:52
  • Hi @RomanPerekhrest, any log can be useful to me which helps to find the lines where the delay is too high. For example: the timestamp of the log entry, the full log entry, the difference between the 2 dates, etc. – Viktor May 16 '18 at 15:16
  • Hi @JeffSchaller, just an example above what has to be examined. There are cases when the difference between starting to get the connection and obtaining it takes many seconds. It seems like a bottleneck and want to investigate why and not just increasing the DB pool. – Viktor May 16 '18 at 15:20

I would approach it with an awk script, below. The script searches for the "obtaining" and "obtained" strings. The typical case is that it finds the "obtaining" string first, followed by the "obtained" string; if an "obtained" line is found first, d1 will be unset or zero, so it won't be reported on. Otherwise, we extract the main part of the date (before the comma), convert that to seconds-since-the-epoch, then add the milliseconds back on. That value is saved into d1.

Once the "obtained" string is seen, its date is computed in the same way, then we check the difference; if it's more than 2 seconds, we report it. Either way, we then reset d1 to start the process over again.

Save the below into a script, named anything you want (perhaps alert-jdbc.awk), then run it with awk -f alert-jdbc.awk < log-file-here.

The script requires the GNU date utility in order to convert arbitrary dates.

/DEBUG Obtaining JDBC connection/ {
  split($1 " " $2, dates, /,/)
  "date -d \"" dates[1]"\" +%s" | getline seconds
  d1=seconds + dates[2]/1000

/DEBUG Obtained JDBC connection/ {
  if (d1) {
    split($1 " " $2, dates, /,/)
    "date -d \"" dates[1]"\" +%s" | getline seconds
    d2=seconds + dates[2]/1000
    if (d2 - d1 > 2) {
        print "More than 2 seconds for: " $0
  • Whaoo... absolutely brilliant! I think Sauron really lives, this is really a black magic. :) Thank you very much, it works perfectly! – Viktor May 16 '18 at 16:08

Try this:

  ($(date -d "`awk '/DEBUG Obtained JDBC connection/{print $1" "$2}' file.log |
  cut -d ',' -f1 | tail -n1`" +%s)) -
  ($(date -d "`awk '/DEBUG Obtaining JDBC connection/{print $1" "$2}' file.log |
  cut -d ',' -f1 | tail -n1`" +%s)) ))
echo "$Delay Sec"

will explain the command if it works for your requirement.

  • Thanks! I can only see the following output: 0 Sec. I'd expect more lines. – Viktor May 16 '18 at 15:13

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.