Welcome, Guest
Username: Password: Remember me

TOPIC: profiling multiple services is not recommended

profiling multiple services is not recommended 2 years 6 months ago #311

Hi,

Could you tell me what the log messages
"p5k: MULTACT3: profiling multiple services is not recommended at input line 72" mean?

In the logfile there are 30 messages and one message which states:
"p5k: DUP: 15 additional occurrences of 'MULTACT3' errors were elided"

MULTACT3 is not in the input trace file as you can see. So what is going wrong?

With kind regards,
Robert

Attachment o072a2_ora_25048_session_trace_energis.zip not found

Attachments:
The administrator has disabled public write access.

Re:profiling multiple services is not recommended 2 years 6 months ago #312

  • Jeff Holt
  • Jeff Holt's Avatar
  • OFFLINE
  • Posts: 103
  • Thank you received: 2
Hi, Robert.

The warning indicates the trace file has more than one distinct client identifier. That happens if the application changes its client identifier through one of the common methods: executing dbms_application_info.set_client_info, using the end-to-end metrics provided by the JDBC, or setting handle attributes in OCI applications.

The warning needs to be modified to say that profiling multiple *clients* is not recommended or something to that effect.

In your trace file you find the first client identifier on line 11, then a null one on line 72, then a different one on line 90. There are only 3 unique values but they reappear over and over again.
$ grep CLIENT *trc | cut -f1 -d')'|sort |uniq
*** CLIENT ID:(
*** CLIENT ID:(eng_cmc3
*** CLIENT ID:(mxsystem
$
Our opinion, which we have spent considerable time justifying, is that the most effective way to address performance problems is to focus on a single user action and find out where the time goes.

It's ok to collect trace data for more than one task execution but if you do you should filter the trace data so that you Profile only one one task execution at a time.

And it's that mindset that caused us to add code to the Profiler that would warn the user that they are Profiling something that we don't recommend. That is, the warning is saying that the user is Profiling more than just one user task execution.

BTW, the user guide has a small paragraph about this warning. You'll find it if you look for MULTACT.

I hope this helps. Let me know if I can help further.
Last Edit: 2 years 6 months ago by Jeff Holt. Reason: spelling mistake
The administrator has disabled public write access.

Re:profiling multiple services is not recommended 2 years 6 months ago #313

Robert,

This message is warning you that the trace file contains more than one combination of MODULE, ACTION, and CLIENT_ID (of DBMS_APPLICATION_INFO and DBMS_SESSION), and therefore probably contains database activity related to more than one business task. The primary purpose of the Profiler is to show where your response time is being spent - for one business task. If the measurement exceeds that one business task, then the generated profile is less helpful.

The MULTACT3 is not meant to represent data found in the trace file - that's our own error name, so that it's easy to find in the User Guide.

In a connection pooled environment, this will be common, of couse, and that's one of the reasons we created the Method R Tools product. With MRTools, you can slice and dice the trace files based on the MODULE, ACTION, and CLIENT_ID to drill down into the database activity for a set of executions for a business task. Hopefully, you set the client identifier as well, with DBMS_SESSION.SET_IDENTIFIER, so that you can drill down into each individual execution of that task.

For example, here's the output from mrskew, one of our MRTools suite for your file. I hope this helps.
$ mrskew *trc --group='"$client_id:$name"' --glabel='Client:Call-Name'
Client:Call-Name                          DURATION       %   CALLS      MEAN       MIN        MAX
--------------------------------------  ----------  ------  ------  --------  --------  ---------
mxsystem:db file sequential read         80.229983   45.6%  57,146  0.001404  0.000118   0.292637
mxsystem:FETCH                           46.660905   26.5%      60  0.777682  0.000000  46.654907
:SQL*Net message from client             28.547422   16.2%     140  0.203910  0.000387   5.008550
mxsystem:gc current block 2-way          10.314861    5.9%  19,340  0.000533  0.000147   0.004993
mxsystem:EXEC                             8.957638    5.1%      36  0.248823  0.000000   8.949640
mxsystem:gc cr grant 2-way                1.088149    0.6%   2,652  0.000410  0.000234   0.001553
mxsystem:SQL*Net message from client      0.103090    0.1%      96  0.001074  0.000395   0.036514
:log file sync                            0.023896    0.0%      13  0.001838  0.001577   0.002375
:EXEC                                     0.021996    0.0%      42  0.000524  0.000000   0.012999
mxsystem:PARSE                            0.009999    0.0%      11  0.000909  0.000000   0.007999
eng_cmc3:SQL*Net message from client      0.009518    0.0%      20  0.000476  0.000396   0.000568
mxsystem:gc cr multi block request        0.008235    0.0%      34  0.000242  0.000020   0.000596
eng_cmc3:EXEC                             0.007999    0.0%      18  0.000444  0.000000   0.001000
mxsystem:row cache lock                   0.006551    0.0%      20  0.000328  0.000044   0.000653
mxsystem:gc cr block 2-way                0.002269    0.0%       4  0.000567  0.000534   0.000620
mxsystem:library cache lock               0.001833    0.0%       4  0.000458  0.000449   0.000465
:PARSE                                    0.001000    0.0%       4  0.000250  0.000000   0.001000
mxsystem:SQL*Net more data from client    0.000544    0.0%       2  0.000272  0.000034   0.000510
:library cache lock                       0.000502    0.0%       1  0.000502  0.000502   0.000502
:SQL*Net message to client                0.000144    0.0%     140  0.000001  0.000000   0.000002
6 others                                  0.000144    0.0%     133  0.000001  0.000000   0.000030
--------------------------------------  ----------  ------  ------  --------  --------  ---------
TOTAL (26)                              175.996678  100.0%  79,916  0.002202  0.000000  46.654907
The administrator has disabled public write access.