Details

    • Type: Bug Bug
    • Status: Closed Closed (View Workflow)
    • Priority: Major Major
    • Resolution: Done
    • Affects Version/s: EAP_EWP 5.1.0
    • Fix Version/s: EAP_EWP 5.1.2 ER1
    • Component/s: EJB
    • Security Level: Public (Everyone can see)
    • Labels:
      None
    • Steps to Reproduce:
      Hide

      1) Deploy the etat.ear

      2) Start up the EAP server

      3) Setup some vars for use by twiddle commands:
      serverUrl='jnp://localhost:1099'
      jmxUser='admin'
      jmxPassword='admin'
      mBeanName='jboss.j2ee:jndiName=TestBean,service=EJB'
      mBeanAttr='DetypedInvocationStatistics'
      mBeanOperation='resetInvocationStats'

      4) Run twiddle to make sure it is working and given a base-line:
      ./twiddle.sh -s "$

      {serverUrl}" -u "${jmxUser}" -p "${jmxPassword}" get "${mBeanName}" "${mBeanAttr}"

      Should see something similar to:
      DetypedInvocationStatistics={#Global={lastResetTime=1304634714452, concurrentCalls=0, maxConcurrentCalls=0}}

      5) Now invoke the EJB using the servlet:
      wget "http://localhost:8080/etatWeb/TestEJBServlet" -a etat.log

      6) Run twiddle again to see that it actually invoked the EJB and we have valid stats:
      ./twiddle.sh -s "${serverUrl}

      " -u "$

      {jmxUser}" -p "${jmxPassword}" get "${mBeanName}" "${mBeanAttr}"

      Should look something like:
      DetypedInvocationStatistics={remove={minTime=1, maxTime=1, count=1, totalTime=1}, create={minTime=121, maxTime=121, count=1, totalTime=121}, sayHello={minTime=3, maxTime=3, count=1, totalTime=3}, #Global={lastResetTime=1304635345747, concurrentCalls=0, maxConcurrentCalls=1}}

      7) And here is how we make things go bad, invoke the resetInvocationStats operation on the EJB using twiddle:
      ./twiddle.sh -s "${serverUrl}" -u "${jmxUser}

      " -p "$

      {jmxPassword}" invoke "${mBeanName}" "${mBeanOperation}"

      8) The resetInvocationStats operation will be successful but look what happens when we get the stats now:
      ./twiddle.sh -s "${serverUrl}" -u "${jmxUser}" -p "${jmxPassword}

      " get "$

      {mBeanName}

      " "$

      {mBeanAttr}

      "

      You should get some wacky results similar to:
      DetypedInvocationStatistics={remove=

      {minTime=9223372036854775807, maxTime=0, count=0, totalTime=0}, create={minTime=9223372036854775807, maxTime=0, count=0, totalTime=0}

      , sayHello=

      {minTime=9223372036854775807, maxTime=0, count=0, totalTime=0}

      , #Global={lastResetTime=1304635363064, concurrentCalls=0, maxConcurrentCalls=0}}

      So, looking at what we get, it is the minTime that is wrong. we should expect it to be 0. This is probably happening because after a reset we should probably expected the stats to look like:
      DetypedInvocationStatistics={#Global=

      {lastResetTime=1304634714452, concurrentCalls=0, maxConcurrentCalls=0}

      }

      Show
      1) Deploy the etat.ear 2) Start up the EAP server 3) Setup some vars for use by twiddle commands: serverUrl='jnp://localhost:1099' jmxUser='admin' jmxPassword='admin' mBeanName='jboss.j2ee:jndiName=TestBean,service=EJB' mBeanAttr='DetypedInvocationStatistics' mBeanOperation='resetInvocationStats' 4) Run twiddle to make sure it is working and given a base-line: ./twiddle.sh -s "$ {serverUrl}" -u "${jmxUser}" -p "${jmxPassword}" get "${mBeanName}" "${mBeanAttr}" Should see something similar to: DetypedInvocationStatistics={#Global={lastResetTime=1304634714452, concurrentCalls=0, maxConcurrentCalls=0}} 5) Now invoke the EJB using the servlet: wget "http://localhost:8080/etatWeb/TestEJBServlet" -a etat.log 6) Run twiddle again to see that it actually invoked the EJB and we have valid stats: ./twiddle.sh -s "${serverUrl} " -u "$ {jmxUser}" -p "${jmxPassword}" get "${mBeanName}" "${mBeanAttr}" Should look something like: DetypedInvocationStatistics={remove={minTime=1, maxTime=1, count=1, totalTime=1}, create={minTime=121, maxTime=121, count=1, totalTime=121}, sayHello={minTime=3, maxTime=3, count=1, totalTime=3}, #Global={lastResetTime=1304635345747, concurrentCalls=0, maxConcurrentCalls=1}} 7) And here is how we make things go bad, invoke the resetInvocationStats operation on the EJB using twiddle: ./twiddle.sh -s "${serverUrl}" -u "${jmxUser} " -p "$ {jmxPassword}" invoke "${mBeanName}" "${mBeanOperation}" 8) The resetInvocationStats operation will be successful but look what happens when we get the stats now: ./twiddle.sh -s "${serverUrl}" -u "${jmxUser}" -p "${jmxPassword} " get "$ {mBeanName} " "$ {mBeanAttr} " You should get some wacky results similar to: DetypedInvocationStatistics={remove= {minTime=9223372036854775807, maxTime=0, count=0, totalTime=0}, create={minTime=9223372036854775807, maxTime=0, count=0, totalTime=0} , sayHello= {minTime=9223372036854775807, maxTime=0, count=0, totalTime=0} , #Global={lastResetTime=1304635363064, concurrentCalls=0, maxConcurrentCalls=0}} So, looking at what we get, it is the minTime that is wrong. we should expect it to be 0. This is probably happening because after a reset we should probably expected the stats to look like: DetypedInvocationStatistics={#Global= {lastResetTime=1304634714452, concurrentCalls=0, maxConcurrentCalls=0} }
    • Release Notes Text:
      Hide
      EJB method invocation statistics returned by the InvocationStatistics MBean would include a value of <Long.MAX_VALUE> for minimum execution time (minTime) after a call to resetStats. The fix is to clear the method invocation statistics list after the resetStats call so that the stats reflect the same state they did when the EJB was first initialized.
      Show
      EJB method invocation statistics returned by the InvocationStatistics MBean would include a value of <Long.MAX_VALUE> for minimum execution time (minTime) after a call to resetStats. The fix is to clear the method invocation statistics list after the resetStats call so that the stats reflect the same state they did when the EJB was first initialized.
    • Release Notes Docs Status:
      Not Required
    • Similar Issues:
      Show 8 results 

      Description

      Issue appears to be with the stats returned by the EJB MBean. The following twiddle command reveals the strange statistics:

      serverUrl='http://localhost:8080'
      jmxUser='admin'
      jmxPassword='admin'
      mBeanName='jboss.j2ee:jndiName=TestBean,service=EJB'
      mBeanAttr='DetypedInvocationStatistics'
      ./twiddle.sh -s "$

      {serverUrl}

      " -u "$

      {jmxUser}

      " -p "$

      {jmxPassword}

      " get
      "$

      {mBeanName}

      " "$

      {mBeanAttr}

      "

      Essentially, you need to deploy the EAR attached to this jira to an EAP 5.1 instance and then push some load to it to see the strange return values.

      1. etat.ear.tar.gz
        3 kB
        Biljana Kramer
      1. CallTimeStatistics_stop1.png
        178 kB

        Issue Links

          Activity

          Hide
          Biljana Kramer
          added a comment -

          This is result that we got when used JON to generate the stats. However, the same strange result is generated when using twiddle command.

          Show
          Biljana Kramer
          added a comment - This is result that we got when used JON to generate the stats. However, the same strange result is generated when using twiddle command.
          Hide
          Larry O'Leary
          added a comment -
          Show
          Larry O'Leary
          added a comment - This issue is a dependency of https://bugzilla.redhat.com/show_bug.cgi?id=690508
          Hide
          Larry O'Leary
          added a comment -

          Okay, I still have not tracked down the actual problem but I have refined the test to actually reproduce the issue on a consistent basis.

          Essentially, install an EAP 5.1 server. Doesn't have to be clustered or anything. My test was based on the all profile but any should work.

          Deploy the etat.ear

          Start up the EAP server

          Setup some vars for use by twiddle commands:
          serverUrl='jnp://localhost:1099'
          jmxUser='admin'
          jmxPassword='admin'
          mBeanName='jboss.j2ee:jndiName=TestBean,service=EJB'
          mBeanAttr='DetypedInvocationStatistics'
          mBeanOperation='resetInvocationStats'

          Run twiddle to make sure it is working and given a base-line:
          ./twiddle.sh -s "$

          {serverUrl}" -u "${jmxUser}" -p "${jmxPassword}" get "${mBeanName}" "${mBeanAttr}"

          Should see something similar to:
          DetypedInvocationStatistics={#Global={lastResetTime=1304634714452, concurrentCalls=0, maxConcurrentCalls=0}}

          Now invoke the EJB using the servlet:
          wget "http://localhost:8080/etatWeb/TestEJBServlet" -a etat.log

          Run twiddle again to see that it actually invoked the EJB and we have valid stats:
          ./twiddle.sh -s "${serverUrl}

          " -u "$

          {jmxUser}" -p "${jmxPassword}" get "${mBeanName}" "${mBeanAttr}"

          Should look something like:
          DetypedInvocationStatistics={remove={minTime=1, maxTime=1, count=1, totalTime=1}, create={minTime=121, maxTime=121, count=1, totalTime=121}, sayHello={minTime=3, maxTime=3, count=1, totalTime=3}, #Global={lastResetTime=1304635345747, concurrentCalls=0, maxConcurrentCalls=1}}

          And here is how we make things go bad, invoke the resetInvocationStats operation on the EJB using twiddle:
          ./twiddle.sh -s "${serverUrl}" -u "${jmxUser}

          " -p "$

          {jmxPassword}" invoke "${mBeanName}" "${mBeanOperation}"

          The operation will be successful but look what happens when we get the stats now:
          ./twiddle.sh -s "${serverUrl}" -u "${jmxUser}" -p "${jmxPassword}

          " get "$

          {mBeanName}

          " "$

          {mBeanAttr}

          "

          You should get some wacky results similar to:
          DetypedInvocationStatistics={remove=

          {minTime=9223372036854775807, maxTime=0, count=0, totalTime=0}, create={minTime=9223372036854775807, maxTime=0, count=0, totalTime=0}

          , sayHello=

          {minTime=9223372036854775807, maxTime=0, count=0, totalTime=0}

          , #Global={lastResetTime=1304635363064, concurrentCalls=0, maxConcurrentCalls=0}}

          So, looking at what we get, it is the minTime that is wrong. we should expect it to be 0. This is probably happening because after a reset we should probably expected the stats to look like:
          DetypedInvocationStatistics={#Global={lastResetTime=1304634714452, concurrentCalls=0, maxConcurrentCalls=0}}

          Show
          Larry O'Leary
          added a comment - Okay, I still have not tracked down the actual problem but I have refined the test to actually reproduce the issue on a consistent basis. Essentially, install an EAP 5.1 server. Doesn't have to be clustered or anything. My test was based on the all profile but any should work. Deploy the etat.ear Start up the EAP server Setup some vars for use by twiddle commands: serverUrl='jnp://localhost:1099' jmxUser='admin' jmxPassword='admin' mBeanName='jboss.j2ee:jndiName=TestBean,service=EJB' mBeanAttr='DetypedInvocationStatistics' mBeanOperation='resetInvocationStats' Run twiddle to make sure it is working and given a base-line: ./twiddle.sh -s "$ {serverUrl}" -u "${jmxUser}" -p "${jmxPassword}" get "${mBeanName}" "${mBeanAttr}" Should see something similar to: DetypedInvocationStatistics={#Global={lastResetTime=1304634714452, concurrentCalls=0, maxConcurrentCalls=0}} Now invoke the EJB using the servlet: wget "http://localhost:8080/etatWeb/TestEJBServlet" -a etat.log Run twiddle again to see that it actually invoked the EJB and we have valid stats: ./twiddle.sh -s "${serverUrl} " -u "$ {jmxUser}" -p "${jmxPassword}" get "${mBeanName}" "${mBeanAttr}" Should look something like: DetypedInvocationStatistics={remove={minTime=1, maxTime=1, count=1, totalTime=1}, create={minTime=121, maxTime=121, count=1, totalTime=121}, sayHello={minTime=3, maxTime=3, count=1, totalTime=3}, #Global={lastResetTime=1304635345747, concurrentCalls=0, maxConcurrentCalls=1}} And here is how we make things go bad, invoke the resetInvocationStats operation on the EJB using twiddle: ./twiddle.sh -s "${serverUrl}" -u "${jmxUser} " -p "$ {jmxPassword}" invoke "${mBeanName}" "${mBeanOperation}" The operation will be successful but look what happens when we get the stats now: ./twiddle.sh -s "${serverUrl}" -u "${jmxUser}" -p "${jmxPassword} " get "$ {mBeanName} " "$ {mBeanAttr} " You should get some wacky results similar to: DetypedInvocationStatistics={remove= {minTime=9223372036854775807, maxTime=0, count=0, totalTime=0}, create={minTime=9223372036854775807, maxTime=0, count=0, totalTime=0} , sayHello= {minTime=9223372036854775807, maxTime=0, count=0, totalTime=0} , #Global={lastResetTime=1304635363064, concurrentCalls=0, maxConcurrentCalls=0}} So, looking at what we get, it is the minTime that is wrong. we should expect it to be 0. This is probably happening because after a reset we should probably expected the stats to look like: DetypedInvocationStatistics={#Global={lastResetTime=1304634714452, concurrentCalls=0, maxConcurrentCalls=0}}
          Hide
          Carlo de Wolf
          added a comment -

          The problem lies in InvocationStatistics.resetStats [1]. By default TimeStatistic.minTime is Long.MAX_VALUE (== 9223372036854775807).

          What I can do is throw away all methodStats on reset, but I'm not familiar with this code and can't comment on any side-effects.

          [1] line 112 of http://viewvc.jboss.org/cgi-bin/viewvc.cgi/jbossas/branches/JBPAPP_5_1/server/src/main/org/jboss/invocation/InvocationStatistics.java?revision=104266&view=markup

          Show
          Carlo de Wolf
          added a comment - The problem lies in InvocationStatistics.resetStats [1] . By default TimeStatistic.minTime is Long.MAX_VALUE (== 9223372036854775807). What I can do is throw away all methodStats on reset, but I'm not familiar with this code and can't comment on any side-effects. [1] line 112 of http://viewvc.jboss.org/cgi-bin/viewvc.cgi/jbossas/branches/JBPAPP_5_1/server/src/main/org/jboss/invocation/InvocationStatistics.java?revision=104266&view=markup
          Hide
          Larry O'Leary
          added a comment -

          Yes, I suspected as much. It seems that throwing away all method stats would truly be resetting it. I can't imagine why we aren't doing this already. In other words, the only method stats that are returned are for methods that have been invoked. So, upon a fresh startup of the EJB, no methods are returned in the invocationStats object to start with. It seems to me that after a reset is performed, the same value should be returned as what was being returned at initial startup of the EJB.

          But, I am in the same realm as you. Not sure how this may impact other code. Seems that if any impact at all, it would be to test cases that hacked around the issue.

          Show
          Larry O'Leary
          added a comment - Yes, I suspected as much. It seems that throwing away all method stats would truly be resetting it. I can't imagine why we aren't doing this already. In other words, the only method stats that are returned are for methods that have been invoked. So, upon a fresh startup of the EJB, no methods are returned in the invocationStats object to start with. It seems to me that after a reset is performed, the same value should be returned as what was being returned at initial startup of the EJB. But, I am in the same realm as you. Not sure how this may impact other code. Seems that if any impact at all, it would be to test cases that hacked around the issue.
          Hide
          Larry O'Leary
          added a comment -

          Committed (svn rev 111905) fix to JBPAPP_5_1 (CP branch) to be included in 5.1.2 release.

          Show
          Larry O'Leary
          added a comment - Committed (svn rev 111905) fix to JBPAPP_5_1 (CP branch) to be included in 5.1.2 release.
          Hide
          Madhumita Sadhukhan
          added a comment -

          Reproduced the steps explained above after deploying etat.ear in EAP 5.1.2.ER1 distribution.
          Obtained results as expected:
          DetypedInvocationStatistics={#Global={lastResetTime=1317890174937, concurrentCalls=0, maxConcurrentCalls=0}}

          Code verification also done.

          Show
          Madhumita Sadhukhan
          added a comment - Reproduced the steps explained above after deploying etat.ear in EAP 5.1.2.ER1 distribution. Obtained results as expected: DetypedInvocationStatistics={#Global={lastResetTime=1317890174937, concurrentCalls=0, maxConcurrentCalls=0}} Code verification also done.

            People

            • Assignee:
              Larry O'Leary
              Reporter:
              Biljana Kramer
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: