12 Replies Latest reply on Nov 17, 2015 12:59 PM by James Perkins

    JBoss log errors

    Sreekanth Munarai Master

      Hi All,

       

      Recently, i have captured few thread dumps as users were complaining about slowness of application.

      Have analysed few below threads which got blocked.

      Not sure is that something need to be fixed at JBoss level or Application level.

      Please find the below thread details:

       

      "pool-10-thread-6856" - Thread t@27716

         java.lang.Thread.State: BLOCKED

                          at java.io.PrintStream.println(PrintStream.java:755)

                          - waiting to lock <67ad764c> (a java.io.PrintStream) owned by "pool-10-thread-6865" t@27769

                          at org.jboss.stdio.StdioContext$DelegatingPrintStream.println(StdioContext.java:297)

                          at org.hibernate.engine.jdbc.spi.SqlStatementLogger.logStatement(SqlStatementLogger.java:106)

                          at org.hibernate.engine.jdbc.spi.SqlStatementLogger.logStatement(SqlStatementLogger.java:95)

                          at org.hibernate.engine.jdbc.internal.proxy.PreparedStatementProxyHandler.(PreparedStatementProxyHandler.java:51)

                          at org.hibernate.engine.jdbc.internal.proxy.ProxyBuilder.buildPreparedStatement(ProxyBuilder.java:114)

                          at org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler.postProcess(ConnectionProxyHandler.java:167)

                          at org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler.continueInvocation(ConnectionProxyHandler.java:139)

                          at org.hibernate.engine.jdbc.internal.proxy.AbstractProxyHandler.invoke(AbstractProxyHandler.java:81)

       

       

      "pool-10-thread-6863" - Thread t@27766

         java.lang.Thread.State: BLOCKED

                          at java.io.PrintStream.println(PrintStream.java:755)

                          - waiting to lock <67ad764c> (a java.io.PrintStream) owned by "pool-10-thread-6865" t@27769

                          at org.jboss.stdio.StdioContext$DelegatingPrintStream.println(StdioContext.java:297)

                          at org.hibernate.engine.jdbc.spi.SqlStatementLogger.logStatement(SqlStatementLogger.java:106)

                          at org.hibernate.engine.jdbc.spi.SqlStatementLogger.logStatement(SqlStatementLogger.java:95)

                          at org.hibernate.engine.jdbc.internal.proxy.PreparedStatementProxyHandler.(PreparedStatementProxyHandler.java:51)

       

      "pool-10-thread-6864" - Thread t@27768

         java.lang.Thread.State: BLOCKED

                          at java.io.PrintStream.println(PrintStream.java:755)

                          - waiting to lock <67ad764c> (a java.io.PrintStream) owned by "pool-10-thread-6865" t@27769

                          at org.jboss.stdio.StdioContext$DelegatingPrintStream.println(StdioContext.java:297)

       

      Please advise me as we are going thru "slowness issue of application"

       

      Thanks,

      Sreekanth

        • 1. Re: JBoss log errors
          James Perkins Master

          It looks like you have Hibernate setup to print SQL statements. So for every JPA query you're writing to stdout. I'd turn that off.

           

          --

          James R. Perkins

          • 2. Re: JBoss log errors
            Sreekanth Munarai Master

            hi James,

             

            Can you please advice how to turn it off and would it have any effect on performance?

             

            Thanks,

            Sreekanth

            • 3. Re: JBoss log errors
              James Perkins Master

              Check your persistence.xml for the hibernate.show_sql parameter. If it's there remove it or set it to false. If it's not there check for an org.hibnerate.SQL logger category.

               

              --

              James R. Perkins

              • 4. Re: JBoss log errors
                Sreekanth Munarai Master

                Hi James,

                 

                I have found below parameter in my standalone.xml:

                <logger category="org.hibernate.SQL">

                                <level name="ERROR"/>

                                <handlers>

                                    <handler name="HIBERNATE"/>

                                </handlers>

                            </logger>



                If i remove the above lines, what would be results? i mean it will stop printing sql queries in logs or do we gonna have any more advantages?

                 

                Can we disable console logging in production? if yes, how can we achieve it?

                 

                Please advise.

                 

                Thanks,

                Sreekanth

                • 5. Re: JBoss log errors
                  Jay SenSharma Master

                  Hello Sreekanth,

                   

                   

                      The meaning of the following logger category is that  for the category "org.hibernate.SQL"   Only the ERROR or higher level logging will happen. (Means it handler "HIBERNATE" won't log any low level logging like there will be NO     TRACE,DEBUG,INFO,WARN logging happen for this category)

                  this is an instruction for JBoss.

                             <logger category="org.hibernate.SQL">

                                  <level name="ERROR"/>

                                  <handlers>

                                      <handler name="HIBERNATE"/>

                                  </handlers>

                              </logger>

                   

                   

                   

                   

                    If i remove the above lines, what would be results? i mean it will stop printing sql queries in logs or do we gonna have any more advantages? 

                    >> You will really need to check your Hibernate Application configuration and make sure that "hibernate.show_sql" is set to "false" (this is an instruction for Hibernate framework).  To stop this logging from where it is actually getting originated.

                        By doing this we instruct Hibernate to not to attempt SQL logging. You will find the  information about "hibernate.show_sql" , which write all SQL statements to console.

                        This is an alternative to setting the log category org.hibernate.SQL to debug.

                   

                   

                            https://docs.jboss.org/hibernate/orm/3.3/reference/en-US/html/session-configuration.html

                  • 6. Re: JBoss log errors
                    James Perkins Master

                    I don't think removing that logger would matter since it's set to ERROR. The SQL statements should be getting logged at a DEBUG level. With your configuration DEBUG messages shouldn't not be getting logged there. You likely need to check your persistence.xml for the hibernate.show_sql property.

                     

                    Can we disable console logging in production? if yes, how can we achieve it?

                    Definitely. With CLI you'd execute the following command, assuming JBoss EAP 6.3 or higher.

                    /subsystem=logging/root-logger=ROOT:remove-handler(name=CONSOLE)
                    

                     

                    If you're on JBoss AS 7.x then:

                    /subsystem=logging/root-logger=ROOT:root-logger-unassign-handler(name=CONSOLE)
                    

                     

                    --

                    James R. Perkins

                    • 7. Re: JBoss log errors
                      Sreekanth Munarai Master

                      Hi James,

                       

                      we have two log files getting generated, one is server.log and hibernate.log. i guess both logs are effecting perform. please find the below log details:

                       

                      ##server.log

                      pool-10-thread-4570) Hibernate:

                      13:47:13,617 INFO  [stdout] (pool-10-thread-4570)     select

                      13:47:13,617 INFO  [stdout] (pool-10-thread-4570)         id,

                      13:47:13,617 INFO  [stdout] (pool-10-thread-4570)         cust_name

                      13:47:13,617 INFO  [stdout] (pool-10-thread-4570)     from

                      13:47:13,617 INFO  [stdout] (pool-10-thread-4570)         dbo.cust_company

                      13:47:13,617 INFO  [stdout] (pool-10-thread-4570)     where

                      13:47:13,617 INFO  [stdout] (pool-10-thread-4570)         is_active='Y'

                      13:47:13,617 INFO  [stdout] (pool-10-thread-4570)         and is_deleted='N'

                      13:47:13,617 INFO  [stdout] (pool-10-thread-4570)         and id in (

                      13:47:13,617 INFO  [stdout] (pool-10-thread-4570)             select

                      13:47:13,617 INFO  [stdout] (pool-10-thread-4570)                 cust_company_xid

                      13:47:13,6

                       

                      ##hibernate.log

                      15 13:43:12 TRACE Found [LWB] as column [col_0_0_]

                      10 Nov 15 13:43:12 TRACE Found [Lewisburg] as column [col_1_0_]

                      10 Nov 15 13:43:12 TRACE Found [LWC] as column [col_0_0_]

                      10 Nov 15 13:43:12 TRACE Found [Lawrence] as column [col_1_0_]

                      10 Nov 15 13:43:12 TRACE Found [LWE] as column [col_0_0_]

                      10 Nov 15 13:43:12 TRACE Found [Lewoleba] as column [col_1_0_]

                      10 Nov 15 13:43:12 TRACE Found [LWG] as column [col_0_0_]

                      10 Nov 15 13:43:12 TRACE Found [Logrono Bus Station] as column [col_1_0_]

                      10 Nov 15 13:43:12 TRACE Found [LWH] as column [col_0_0_]

                       

                       

                      Please can you advice me where i can make changes in my standalone.xml file to disable above logging?below is snippet of the standalone.xml.

                       

                      size-rotating-file-handler name="HIBERNATE" autoflush="true">

                                      <level name="TRACE"/>

                                      <formatter>

                                          <pattern-formatter pattern="%d{dd MMM yyy HH:mm:ss} %-5p %m%n"/>

                                      </formatter>

                                      <file relative-to="jboss.server.log.dir" path="D:\Logs\Online\homeport\system\hibernate.log"/>

                                      <rotate-size value="20480k"/>

                                      <max-backup-index value="200"/>

                                      <append value="true"/>

                                  </size-rotating-file-handler>

                                  <logger category="com.arjuna">

                                      <level name="WARN"/>

                                  </logger>

                                  <logger category="org.apache.tomcat.util.modeler">

                                      <level name="WARN"/>

                                  </logger>

                                  <logger category="sun.rmi">

                                      <level name="WARN"/>

                                  </logger>

                                  <logger category="org.hibernate.SQL">

                                      <level name="TRACE"/>

                                      <handlers>

                                          <handler name="HIBERNATE"/>

                                      </handlers>

                                  </logger>

                                  <logger category="org.hibernate.type">

                                      <level name="TRACE"/>

                                      <handlers>

                                          <handler name="HIBERNATE"/>

                                      </handlers>

                                  </logger>

                                  <root-logger>

                                      <level name="INFO"/>

                                      <handlers>

                                          <handler name="CONSOLE"/>

                                          <handler name="FILE"/>

                                      </handlers>

                                  </root-logger>

                              </subsystem>



                      Thanks,

                      • 8. Re: JBoss log errors
                        James Perkins Master

                        You've got a HIBERNATE handler and two org.hibernate.* loggers set to TRACE. Just remove those or change the level to something greater than TRACE.

                         

                        With the server.log those are coming from your persistence.xml properties. The hibernate.show_sql property needs to be removed.

                         

                        --

                        James R. Perkins

                        • 9. Re: JBoss log errors
                          Sreekanth Munarai Master

                          Hi James,

                           

                          Thanks for the suggestions. Will be removing the below two tags from standalone.xml file:

                          <logger category="org.hibernate.SQL">

                                          <level name="TRACE"/>

                                          <handlers>

                                              <handler name="HIBERNATE"/>

                                          </handlers>

                                      </logger>

                                      <logger category="org.hibernate.type">

                                          <level name="TRACE"/>

                                          <handlers>

                                              <handler name="HIBERNATE"/>

                                          </handlers>

                                      </logger>



                          But I am unable to find "hibernate.show_sql " property anywhere in my xml file. Where i can find this property?

                           

                          Thanks,
                          Sreekanth

                          • 10. Re: JBoss log errors
                            Jay SenSharma Master

                            Hello Sreekanth,

                             

                            The SQL statement console logging which you were referring was coming from "org.hibernate.SQL". See: https://docs.jboss.org/hibernate/orm/3.3/reference/en-US/html/session-configuration.html

                             

                            "hibernate.show_sql" Write all SQL statements to console. This is an **Alternative** to setting the log category "org.hibernate.SQL" to debug.

                             

                            There are two possibilities to enable or disable it:

                             

                            1). By setting "hibernate.show_sql"  property to true in persistence.xml file or any of your hibernate configuration file. As you mentioned that you do not have any such file in your application which contains this property, Which means that it was coming because of your following configuration.

                             

                            2). By setting the [logger category="org.hibernate.SQL"] to "TRACE"/ "DEBUG", Which you were doing in your "standalone.xml" file.  (that need to be removed)

                             

                            As you do not have  "hibernate.show_sql" property set anywhere so in that case you should also remove the "org.hibernate.SQL".  Or need to set it to a higher logging level like "INFO"


                            Regards

                            Jay SenSharma

                            • 11. Re: JBoss log errors
                              Sreekanth Munarai Master

                              Hi Jay,

                               

                              Thanks for your valuable suggestions.Will be making changes in xml file as recommended.

                              My application team recommends to change log level from "Trace" to "Error" instead of "INFO". As per their understanding, INFO logging will capture each and every query of SQL which would cause impact, whereas ERROR would be listing only errors. Any advice?

                               

                              Thanks,

                              Sreekanth

                              • 12. Re: JBoss log errors
                                James Perkins Master

                                The reason I think the hibernate.show_sql is set in the persistence.xml is there are log messages going to System.out in the server.log. If you enable the logger, org.hibernate.SQL, then it should be using a logger and not System.out. Note that the hibernate.show_sql property will not be in the standalone.xml file. It will be in a configuration file in your deployment.

                                 

                                As far as setting the level to ERROR instead of TRACE that would work, but also in this case doesn't make sense. AFAIK the only thing that org.hibernate.SQL logs is SQL statements. Setting it to INFO won't hurt and would stop the TRACE messages from being printed, but so will removing the logger configuration all together.

                                 

                                --

                                James R. Perkins