Jooq: Significant time spent in OffsetDateTime.parse() when reading OffsetDateTime fields

[lukaseder]

There seems to be a significant performance issue in the OffsetDateTime.parse() method as can be seen in a profiling session when running 10000 queries that produce 10000 TIMESTAMP WITH TIME ZONE values in PostgreSQL:

Further analysis is required

---

See also:
https://groups.google.com/forum/#!topic/jooq-user/5FZQY_5dKjo

[lukaseder]

We cannot easily call ResultSet.getObject(i, OffsetDateTime.class) in PostgreSQL, as that seems to return a timestamp in UTC, not in local time zone as ResultSet.getString(i) does. This would have to be done separately, in a minor release as a backwards incompatible issue

[marshallpierce]

Argh, time zone handling in JDBC is such a pain. I didn't notice that issue in my own testing because I use "SET TIME ZONE 'UTC'" in my pool's connection init.

[lukaseder]

I didn't notice that issue in my own testing because I use "SET TIME ZONE 'UTC'" in my pool's connection init.

That's always a good idea. I think the getString() method is correct, because it is consistent with e.g. psql. The database reports TIMESTAMP WITH TIME ZONE in the local time zone. The JDBC driver is trying to be clever in the getObject() method. Here's a snippet:

    } else if (type == OffsetDateTime.class) {
      if (sqlType == Types.TIMESTAMP_WITH_TIMEZONE || sqlType == Types.TIMESTAMP) {
        Timestamp timestampValue = getTimestamp(columnIndex);
        if (wasNull()) {
          return null;
        }
        long time = timestampValue.getTime();
        if (time == PGStatement.DATE_POSITIVE_INFINITY) {
          return type.cast(OffsetDateTime.MAX);
        }
        if (time == PGStatement.DATE_NEGATIVE_INFINITY) {
          return type.cast(OffsetDateTime.MIN);
        }
        // Postgres stores everything in UTC and does not keep original time zone
        OffsetDateTime offsetDateTime = OffsetDateTime.ofInstant(timestampValue.toInstant(), ZoneOffset.UTC);
        return type.cast(offsetDateTime);
      } else {
        throw new PSQLException(GT.tr("conversion to {0} from {1} not supported", type, sqlType),
                PSQLState.INVALID_PARAMETER_VALUE);
      }

I've reported this to the JDBC driver people: https://github.com/pgjdbc/pgjdbc/issues/1324

The fix for the performance issue will try to improve the parse speed.

[marshallpierce]

I think the JDBC spec says that the driver should return objects in the TZ of the JVM (allegedly a requirement stemming from setTimestamp, according to legend), which if true would mean:

• It's a bug in the PostgreSQL driver that it's not returning them that way (though the docs do make it clear that that will happen https://jdbc.postgresql.org/documentation/head/java8-date-time.html)
• It can be fixed after the fact via atZoneSameInstant perhaps.

[lukaseder]

That's valid for fetching java.sql.Timestamp. Unfortunately, everyone pretty much screwed up the TIMESTAMP WITH TIME ZONE data type in various ways. The SQL standard and JDBC specify that it has java.time.OffsetDateTime semantics. Oracle implements a clever union of OffsetDateTime|ZonedDateTime, and PostgreSQL implements java.time.Instant. So, everyone kinda got it "wrong" for different reasons.

It can be fixed after the fact via atZoneSameInstant perhaps.

You'd think so. But which time zone should be taken? Server or client time zone?

Perhaps I'll just write my own stupid parser :-) (I have to fix so many things anyway prior to passing the string version to OffsetDateTime.parse(), and those fixes also take a significant amount of time)

[lukaseder]

Yeah, I'll roll my own parser. That's definitely much better than the status quo. How hard can it be

[marshallpierce]

It's not always the wrong thing to do...

[lukaseder]

Confirmed: https://twitter.com/mjpt777/status/1055807459867181058 and https://twitter.com/mjpt777/status/1055807167369043968 ;-)

[lukaseder]

Definitely much better to roll my own. After the refactoring, here's the JMC output for the same benchmark. All the work is now being done downstream of jOOQ, inside of the JDBC driver or the database:

This isn't perfect yet. It would be better to directly load the OffsetDateTime object from the driver, but I'll have to first check what the JDBC people will say about my concerns. I'll postpone that other task to later: #7987

This fix here just modifies the parser logic, and thus can be backported easily to older patch releases, including 3.11.6 and 3.10.9

[lukaseder]

Fixed in jOOQ 3.12.0. Backports scheduled for 3.11.6 (#7988) and 3.10.9 (#7989)

[lukaseder]

JMH benchmark

public class OffsetDateTimeParsingBenchmark {

    @Warmup(iterations = 2, batchSize = 3)
    @Measurement(iterations = 5, batchSize = 4)
    @Fork(3)
    @Benchmark
    public Result<?> testMethod() {
        return
            ctx.select(t, u)
               .from("(select "
                   + "timestamp with time zone '2000-01-01 00:00:00+03:00' + interval '1 seconds' * y as t,"
                   + "time with time zone '00:00:00+03:00' + interval '1 seconds' * y as u "
                   + "from generate_series(1, 100) x(y)) x")
               .fetch();
    }

    static Field<OffsetDateTime> t = DSL.field("t", SQLDataType.TIMESTAMPWITHTIMEZONE);
    static Field<OffsetTime> u = DSL.field("u", SQLDataType.TIMEWITHTIMEZONE);
    static DSLContext ctx;

    static {
        try {
            Class.forName("org.postgresql.Driver");

            Connection connection = DriverManager.getConnection(
                "jdbc:postgresql://localhost:5432/postgres",
                "postgres",
                "test");
            Settings s = new Settings().withExecuteLogging(false);
            ctx = DSL.using(connection, s);
        }
        catch (Exception e) {
            throw new DataAccessException("", e);
        }
    }
}

Before the fix

OffsetDateTimeParsingBenchmark.testMethod  thrpt   15  290.151 ± 21.424  ops/s

After the fix

OffsetDateTimeParsingBenchmark.testMethod  thrpt   15  871.238 ± 35.147  ops/s

The improvement is almost 3x the speed for running queries that fetch 100 of these timestamps. With only 100 rows returned per query, the overhead of the query is still quite significant. For larger result sets, the improvement of the parser will be much more drastic.

@marshallpierce If you would like to build jOOQ from GitHub master and provide quick feedback here or on the mailing list, comparing the execution speeds between version 3.11.5 and 3.12.0-SNAPSHOT, that would be greatly appreciated.

[marshallpierce]

btw, building from f7dfa816b fails out of the box because the H2 dependency is set to 1.4.198-SNAPSHOT, which isn't available in the snapshot repo, so I'm using 1.4.197, which I assume shouldn't make any difference for the purposes of this test.

Code gen fails using the gradle 3.0.2 plugin:

WARNING: Unmarshal warning        : cvc-elt.1.a: Cannot find the declaration of element 'configuration'.
Oct 26, 2018 10:10:10 AM org.jooq.tools.JooqLogger warn
WARNING: Unmarshal warning        : unexpected element (uri:"http://www.jooq.org/xsd/jooq-codegen-3.12.0.xsd", local:"configuration"). Expected elements are <{http://www.jooq.org/xsd/jooq-codegen-3.11.0.xsd}configuration>
Oct 26, 2018 10:10:10 AM org.jooq.tools.JooqLogger error
SEVERE: Cannot read /home/mbp/dev/molecular-instruments/mi-webapp/api-svc/svc/build/tmp/generateApiSvcJooqSchemaSource/config.xml. Error : Error while reading XML configuration
org.jooq.codegen.GeneratorException: Error while reading XML configuration
        at org.jooq.codegen.GenerationTool.load(GenerationTool.java:938)
        at org.jooq.codegen.GenerationTool.main(GenerationTool.java:194)
Caused by: javax.xml.bind.UnmarshalException: unexpected element (uri:"http://www.jooq.org/xsd/jooq-codegen-3.12.0.xsd", local:"configuration"). Expected elements are <{http://www.jooq.org/xsd/jooq-codegen-3.11.0.xsd}configuration>
        at com.sun.xml.bind.v2.runtime.unmarshaller.UnmarshallingContext.handleEvent(UnmarshallingContext.java:744)
        at com.sun.xml.bind.v2.runtime.unmarshaller.Loader.reportError(Loader.java:262)
        at com.sun.xml.bind.v2.runtime.unmarshaller.Loader.reportError(Loader.java:257)
        at com.sun.xml.bind.v2.runtime.unmarshaller.Loader.reportUnexpectedChildElement(Loader.java:124)
        at com.sun.xml.bind.v2.runtime.unmarshaller.UnmarshallingContext$DefaultRootLoader.childElement(UnmarshallingContext.java:1149)
        at com.sun.xml.bind.v2.runtime.unmarshaller.UnmarshallingContext._startElement(UnmarshallingContext.java:574)
        at com.sun.xml.bind.v2.runtime.unmarshaller.UnmarshallingContext.startElement(UnmarshallingContext.java:556)
        at com.sun.xml.bind.v2.runtime.unmarshaller.ValidatingUnmarshaller.startElement(ValidatingUnmarshaller.java:102)
        at com.sun.xml.bind.v2.runtime.unmarshaller.SAXConnector.startElement(SAXConnector.java:168)
        at java.xml/com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.startElement(AbstractSAXParser.java:509)
        at java.xml/com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.scanStartElement(XMLNSDocumentScannerImpl.java:374)
        at java.xml/com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl$NSContentDriver.scanRootElementHook(XMLNSDocumentScannerImpl.java:613)
        at java.xml/com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl$FragmentContentDriver.next(XMLDocumentFragmentScannerImpl.java:3058)
        at java.xml/com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl$PrologDriver.next(XMLDocumentScannerImpl.java:821)
        at java.xml/com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(XMLDocumentScannerImpl.java:602)
        at java.xml/com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.next(XMLNSDocumentScannerImpl.java:112)
        at java.xml/com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(XMLDocumentFragmentScannerImpl.java:532)
        at java.xml/com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:888)
        at java.xml/com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:824)
        at java.xml/com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(XMLParser.java:141)
        at java.xml/com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(AbstractSAXParser.java:1213)
        at java.xml/com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(SAXParserImpl.java:635)
        at com.sun.xml.bind.v2.runtime.unmarshaller.UnmarshallerImpl.unmarshal0(UnmarshallerImpl.java:258)
        at com.sun.xml.bind.v2.runtime.unmarshaller.UnmarshallerImpl.unmarshal(UnmarshallerImpl.java:229)
        at javax.xml.bind.helpers.AbstractUnmarshallerImpl.unmarshal(AbstractUnmarshallerImpl.java:170)
        at javax.xml.bind.helpers.AbstractUnmarshallerImpl.unmarshal(AbstractUnmarshallerImpl.java:219)
        at org.jooq.codegen.GenerationTool.load(GenerationTool.java:928)
        ... 1 more

Backport to 3.11 so I can try it there? I did my previous hacking around off of the 3.11.5 tag and didn't have issues, as you would expect.

[lukaseder]

Egh. Thanks for the pointers. The H2 dependency has been updated because jOOQ 3.12 already supports some not-yet-published H2 features, like window functions. It shouldn't be referenced from the jOOQ Open Source Edition, though. This should definitely be fixed.

I'll look into the gradle issue, thanks for pointing that out.

You could definitely backport the fix to 3.11 and try it there, to get less side effects. Thanks a lot for taking the time to do this!

[lukaseder]

Oh, when you say gradle, do you use the third party plugin? https://github.com/etiennestuder/gradle-jooq-plugin, or do you call the GenerationTool directly, programmatically (the stack trace indicates the latter)

[marshallpierce]

Yes, I'm using the third party plugin (version 3.0.2) to do the code gen, not running the tool myself. I trimmed the generic Gradle output from the error, sorry for the confusion.

This is my gradle plugin config:

jooq {
  version = '3.11.5'

  apiSvc(sourceSets.main) {
    jdbc {
      driver = 'org.postgresql.Driver'
      url = jdbcUrl
      user = dbUser
      password = dbPass
    }
    generator {
      target {
        packageName = 'com.foo.bar'
      }
      database {
        inputSchema = 'public'
        excludes = 'flyway_schema_history'
      }
      generate {
        // causes issues with module path
        generatedAnnotation = false
        pojos = true
        javaTimeTypes = true
      }
    }
  }
}

Edit: I'll look into backporting to 3.11 later today.

[marshallpierce]

Upon cherry-picking f7dfa816b2d28b3e40ef4816042955aae9a51916 onto 3.11.5 and fixing the conflicts, I'm getting a steady state "query time" (according to my sloppy benchmark) of 2s instead of 3s, so I'd say it's working. Profiler shows parsing ODTs is now less than the time taken to parse strings instead of dominating the profile.

[lukaseder]

Excellent, thank you very much for the feedback, @marshallpierce. I'll definitely release 3.11.6 this week with this fix!

[lukaseder]

For the record, I now have an Open JDK user account and reported this issue, which will hopefully be addressed:
https://bugs.openjdk.java.net/browse/JDK-8213243