How do I match changing connection numbers with cumulative properties?

[Breck_Carter]

Apparently, when a 12.0.1.3298 web service connection in the pool is reused for repeated invocations of the same web service, a new connection number is assigned but connection-level properties like ApproximateCPUTime are accumulated across the different connection numbers:

                         connection number        
                         |    web service user id         
                         |    |         ApproximateCPUTime
                         |    |         |
                         V    V         V
2012-07-04 08:06:28.335  79   DBA_menu  50.264986
2012-07-04 08:06:37.619  79   DBA_menu  51.139994
2012-07-04 08:06:47.564  81   DBA_menu  53.452595
2012-07-04 08:06:57.474  83   DBA_menu  54.483866
2012-07-04 08:07:07.448  85   DBA_menu  56.874496
2012-07-04 08:07:17.390  87   DBA_menu  57.890099
2012-07-04 08:07:27.678  89   DBA_menu  60.218163
2012-07-04 08:07:37.374  89   DBA_menu  60.218163
2012-07-04 08:07:47.425  91   DBA_menu  61.233766
2012-07-04 08:07:57.467  93   DBA_menu  63.343206
2012-07-04 08:08:07.453  95   DBA_menu  64.343245
2012-07-04 08:08:17.560  97   DBA_menu  65.905766
2012-07-04 08:08:27.689  99   DBA_menu  66.921370
2012-07-04 08:08:37.575  101  DBA_menu  67.936973
2012-07-04 08:08:47.654  103  DBA_menu  68.358861
2012-07-04 08:08:57.542  103  DBA_menu  69.046374
2012-07-04 08:09:07.549  105  DBA_menu  70.046310

How do I associate the different connection numbers with one another when calculating increases in ApproximateCPUTime?

Or... am I nuts? 🙂

[ian_mchardy · Accepted solution]

The connection numbers are expected to increase (pooling attempts to avoid changing behavior as much as possible, although option values are not cleared when reusing a HTTP/HTTPS connection for performance reasons).

The ApproximateCPUTime value should have only been for the single HTTP request (just like it would have been if the connection was not pooled). This has been fixed by engineering issue 713914.

Are there other connection properties that are "accumulated across the different connection numbers"?

[Breck_Carter · Accepted solution]

Thanks!

I will have a look at the properties Foxhound cares about, let you know one way or the other about each.

[Breck_Carter · Accepted solution]

Ian: Only one more suspicious property to report: LoginTime remains constant, and (probably) dates back to the moment of the first call to the web service; see below.

HOWEVER, my investigation was inadequate for several reasons:

• Most property values remain zero so it's impossible to tell if they are accumulating,

• other property values remain constant and it's impossible to tell if that's OK or not (e.g., QueryOptimized = 26 and QueryReused = 107), and

• Foxhound doesn't gather all connection properties.

                         connection number        
                         |     web service user id         
                         |     |         ApproximateCPUTime
                         |     |         |           LoginTime
                         |     |         |           |
                         V     V         V           V
2012-07-10 17:47:42.260  2411  DBA_menu  238.705971  2012-07-10 14:23:22.466000
2012-07-10 17:47:50.784  2411  DBA_menu  238.705971  2012-07-10 14:23:22.466000
2012-07-10 17:48:00.878  2413  DBA_menu  238.846566  2012-07-10 14:23:22.466000
2012-07-10 17:48:10.895  2415  DBA_menu  239.002829  2012-07-10 14:23:22.466000
2012-07-10 17:48:20.991  2417  DBA_menu  239.159091  2012-07-10 14:23:22.466000
2012-07-10 17:48:30.915  2427  DBA_menu  239.690445  2012-07-10 14:23:22.466000
2012-07-10 17:48:40.961  2431  DBA_menu  239.940506  2012-07-10 14:23:22.466000
2012-07-10 17:48:50.895  2433  DBA_menu  240.174899  2012-07-10 14:23:22.466000
2012-07-10 17:49:00.904  2435  DBA_menu  240.393626  2012-07-10 14:23:22.466000
2012-07-10 17:49:10.937  2439  DBA_menu  241.049805  2012-07-10 14:23:22.466000
2012-07-10 17:49:20.945  2445  DBA_menu  241.581056  2012-07-10 14:23:22.466000
2012-07-10 17:49:30.864  2451  DBA_menu  242.034278  2012-07-10 14:23:22.466000
2012-07-10 17:49:40.853  2457  DBA_menu  242.846618  2012-07-10 14:23:22.466000
2012-07-10 17:49:50.878  2463  DBA_menu  243.299738  2012-07-10 14:23:22.466000

[Breck_Carter · Accepted solution]

Ian: Would you like me to do a thorough investigation?

Please say, "No, that's our responsibility, and we can look at the code." 🙂

[ian_mchardy · Accepted solution]

I have also fixed connection_property( 'LoginTime' ) so it is reset when the connection is reused and included it with engineering issue 713914. As far as I know, other properties should already get reset when a pooled connection is being reused. I asked if there were others because of the way you asked the question implied you may have seen others.

[Breck_Carter · Accepted solution]

the way you asked the question implied you may have seen others

Oops, sorry... at that point I thought the behavior was intended so I assumed it would apply to other properties as well. It's hard to tell from the end result (actual property values) where they came from; i.e., when you're standing in a septic tank (the end results) it's hard to tell the steak from the potatoes (where it came from).

No offense intended, however... just an analogy to demonstrate that when f(x) = y, knowing y sometimes tells you very little about x 🙂