OpenJPA
  1. OpenJPA
  2. OPENJPA-1585

Additional trace to relate SQL pushdowns with entity action or JPQL query

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Trivial Trivial
    • Resolution: Fixed
    • Affects Version/s: 2.0.0
    • Fix Version/s: 2.0.0-beta3
    • Component/s: None
    • Labels:
      None

      Description

      Additional trace can help users understand and relate query or entity actions with SQL pushdowns:
      1. why SQL pushdown has JOINs that are generated, a trace dumping out eager relations for the generated SQL is very helpful.
      2. a JPQL or a simple em.find() generated caused more than one SQL requests.
      3. entity instance actions (INSERT, UPDATE, DELETE) generated SQL

      Examples:
      1. JOIN is generated because of the eager relation 'entitya':
      4891 p1 TRACE [main] openjpa.Query - Executing query: select s from CascadeB s
      4906 p1 TRACE [main] openjpa.jdbc.Extra - Eager relations: [test.entities.CascadeB.entitya]
      5141 p1 TRACE [main] openjpa.jdbc.SQL - <t 26882784, conn 9493> executing prepstmnt 25862088 SELECT t0.id, t1.id, t1.name, t0.name FROM CascadeB t0 LEFT OUTER JOIN CascadeA t1 ON t0.ENTITYA_ID = t1.id

      2. flush for new instance of entity action:
      7250 p1 TRACE [main] openjpa.jdbc.Extra - flush: org.apache.openjpa.kernel.PNewState for oid=1
      7250 p1 TRACE [main] openjpa.jdbc.SQL -: INSERT INTO BasicA (age,id,name) VALUES (?,?,?) [1,1,name1]

      2: loading relation 'entitya':
      7734 p1 TRACE [main] openjpa.jdbc.Extra - load field: 'entitya' for oid=1 class test.entities.BasicB
      7734 p1 TRACE [main] openjpa.jdbc.Extra - find: oid=1 class test.entities.BasicA
      7734 p1 TRACE [main] openjpa.jdbc.Extra - getInitializeStateResult: oid=1 class test.entities.BasicA
      7969 pdq1 TRACE [main] openjpa.jdbc.SQL - <t 26882784, conn 3125250> executing prepstmnt 28008463 SELECT t0.name FROM BasicA t0 WHERE t0.id = ? optimize for 1 row [params=(int) 1]

      1. OPENJPA-1585.patch
        9 kB
        Catalina Wei
      2. ASF.LICENSE.NOT.GRANTED--graycol.gif
        0.1 kB
        Catalina Wei
      3. ASF.LICENSE.NOT.GRANTED--ecblank.gif
        0.0 kB
        Catalina Wei

        Activity

        Hide
        Catalina Wei added a comment -

        In this patch, a trace channel named 'openjpa.jdbc.Extra' is defined for getting additional trace information that may help users relate the SQLs generated to entity activities or JPQL queries.

        To turn on this trace, add as below:

        <property name="openjpa.Log" value="Query=TRACE,SQL=TRACE,Extra=TRACE"/>

        It would only make sense to turn on Extra trace when Query and SQL traces are also turned on.

        Show
        Catalina Wei added a comment - In this patch, a trace channel named 'openjpa.jdbc.Extra' is defined for getting additional trace information that may help users relate the SQLs generated to entity activities or JPQL queries. To turn on this trace, add as below: <property name="openjpa.Log" value="Query=TRACE,SQL=TRACE,Extra=TRACE"/> It would only make sense to turn on Extra trace when Query and SQL traces are also turned on.
        Hide
        Pinaki Poddar added a comment -

        1. How about adding these useful trace statements to SQL=TRACE level itself instead of having an extra channel.
        2. The trace messages use non-localized hard coded Strings. Generally that is not done for other parts of the code base.

        Show
        Pinaki Poddar added a comment - 1. How about adding these useful trace statements to SQL=TRACE level itself instead of having an extra channel. 2. The trace messages use non-localized hard coded Strings. Generally that is not done for other parts of the code base.
        Hide
        Catalina Wei added a comment -

        Hi Pinaki,
        Thanks for your comment.
        Yes, it would be nice to introduce another level of tracing
        (openjpa.jdbc.SQL=DIAG level),
        but that involves changing the Log interface, and I found that the
        com.ibm.ws.jpa.management.TraceLogChannel implements Log interface.
        I was afraid of any build/compile breaks at this time since we are about to
        cut 2.0.0 branch.
        I will take another shot at this after we have that done and work on it at
        trunk code.

        as far as message ids, there are lots of trace messages that we logged were
        non-localized messages.
        It seems that if trace messages is providing information that user need to
        take some action, then a message id should be used.
        Because messages will get translated into different languages and users
        other than US-speakings would know what actions to take.

        The diagnostic trace that I added are mostly informational, no actions were
        given to users. So I think it should be OK with non-localized messages.

        Thanks again.

        Regards, Catalina

        Department: DMQA
        e-mail: fancy@us.ibm.com
        Tie: 543-3290

        From: "Pinaki Poddar (JIRA)" <jira@apache.org>

        To: Catalina Wei/Silicon Valley/IBM@IBMUS

        Date: 03/22/2010 07:57 AM

        Subject: [jira] Commented: (OPENJPA-1585) Additional trace to relate SQL pushdowns with entity action or
        JPQL query

        [
        https://issues.apache.org/jira/browse/OPENJPA-1585?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12848152#action_12848152
        ]

        Pinaki Poddar commented on OPENJPA-1585:
        ----------------------------------------

        1. How about adding these useful trace statements to SQL=TRACE level itself
        instead of having an extra channel.
        2. The trace messages use non-localized hard coded Strings. Generally that
        is not done for other parts of the code base.

        actions with SQL pushdowns:
        eager relations for the generated SQL is very helpful.
        requests.
        CascadeB s
        [test.entities.CascadeB.entitya]
        executing prepstmnt 25862088 SELECT t0.id, t1.id, t1.name, t0.name FROM
        CascadeB t0 LEFT OUTER JOIN CascadeA t1 ON t0.ENTITYA_ID = t1.id
        org.apache.openjpa.kernel.PNewState for oid=1
        (age,id,name) VALUES (?,?,?) [1,1,name1]
        oid=1 class test.entities.BasicB
        test.entities.BasicA
        oid=1 class test.entities.BasicA
        executing prepstmnt 28008463 SELECT t0.name FROM BasicA t0 WHERE t0.id = ?
        optimize for 1 row [params=(int) 1]


        This message is automatically generated by JIRA.
        -
        You can reply to this email to add a comment to the issue online.

        Show
        Catalina Wei added a comment - Hi Pinaki, Thanks for your comment. Yes, it would be nice to introduce another level of tracing (openjpa.jdbc.SQL=DIAG level), but that involves changing the Log interface, and I found that the com.ibm.ws.jpa.management.TraceLogChannel implements Log interface. I was afraid of any build/compile breaks at this time since we are about to cut 2.0.0 branch. I will take another shot at this after we have that done and work on it at trunk code. as far as message ids, there are lots of trace messages that we logged were non-localized messages. It seems that if trace messages is providing information that user need to take some action, then a message id should be used. Because messages will get translated into different languages and users other than US-speakings would know what actions to take. The diagnostic trace that I added are mostly informational, no actions were given to users. So I think it should be OK with non-localized messages. Thanks again. Regards, Catalina Department: DMQA e-mail: fancy@us.ibm.com Tie: 543-3290 From: "Pinaki Poddar (JIRA)" <jira@apache.org> To: Catalina Wei/Silicon Valley/IBM@IBMUS Date: 03/22/2010 07:57 AM Subject: [jira] Commented: ( OPENJPA-1585 ) Additional trace to relate SQL pushdowns with entity action or JPQL query [ https://issues.apache.org/jira/browse/OPENJPA-1585?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12848152#action_12848152 ] Pinaki Poddar commented on OPENJPA-1585 : ---------------------------------------- 1. How about adding these useful trace statements to SQL=TRACE level itself instead of having an extra channel. 2. The trace messages use non-localized hard coded Strings. Generally that is not done for other parts of the code base. actions with SQL pushdowns: eager relations for the generated SQL is very helpful. requests. CascadeB s [test.entities.CascadeB.entitya] executing prepstmnt 25862088 SELECT t0.id, t1.id, t1.name, t0.name FROM CascadeB t0 LEFT OUTER JOIN CascadeA t1 ON t0.ENTITYA_ID = t1.id org.apache.openjpa.kernel.PNewState for oid=1 (age,id,name) VALUES (?,?,?) [1,1,name1] oid=1 class test.entities.BasicB test.entities.BasicA oid=1 class test.entities.BasicA executing prepstmnt 28008463 SELECT t0.name FROM BasicA t0 WHERE t0.id = ? optimize for 1 row [params=(int) 1] – This message is automatically generated by JIRA. - You can reply to this email to add a comment to the issue online.

          People

          • Assignee:
            Catalina Wei
            Reporter:
            Catalina Wei
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development