| Author |
Message
|
| kotagiriaashish |
 Posted: Wed Jan 04, 2012 5:00 am Post subject: |
 |
|
Disciple
Joined: 06 Aug 2011
Posts: 165
|
| JasonE wrote: |
Are you connecting / disconnecting each time - that would be the first step.
Trace a portion of the client side, then grep the trace for >> and <<, and work out the time differences from the entry to the exit for each API call, to give an indication of (a) the API calls being made (conn, open, put, close, disc etc), and (b) where the time is being spent. If you put a trace somewhere I can access it, I dont mind taking a quick look as I have a tool which helps with this.
Any idea what language is the app written in (.net? C? java? C++?)? |
The program is written in C... I am willing to provide the trace... but please name the trace, which trace do you want me to post? I will get it to you Right away... |
|
| Back to top |
|
 |
| JasonE |
| Posted: Wed Jan 04, 2012 5:09 am Post subject: |
|
|
Grand Master
Joined: 03 Nov 2003
Posts: 1220
Location: Hursley
|
| If its client side, you get one trace file per process, and assuming your app is a single process then its that one (strmqtrc, let it run, endmqtrc, look in the trace dir for AMQxxxx.y.trc)... where xxxxx is the process id |
|
| Back to top |
|
|
| kotagiriaashish |
| Posted: Wed Jan 04, 2012 12:08 pm Post subject: |
|
|
Disciple
Joined: 06 Aug 2011
Posts: 165
|
| Code: |
22:30:51.439387 4896.1 RSESS:000002 !! - MQPUT >>
22:30:52.928716 4896.1 RSESS:000002 !! - MQPUT <<
489 ms approx...
|
What do you think?? |
|
| Back to top |
|
|
| fjb_saper |
| Posted: Wed Jan 04, 2012 12:19 pm Post subject: |
|
|
Grand High Poobah
Joined: 18 Nov 2003
Posts: 20763
Location: LI,NY
|
| kotagiriaashish wrote: |
| Code: |
22:30:51.439387 4896.1 RSESS:000002 !! - MQPUT >>
22:30:52.928716 4896.1 RSESS:000002 !! - MQPUT <<
489 ms approx...
|
What do you think?? |
You mean to say: 1.489329 seconds for the put. What was the size of the message? 
_________________
MQ & Broker admin |
|
| Back to top |
|
|
| kotagiriaashish |
| Posted: Wed Jan 04, 2012 12:27 pm Post subject: |
|
|
Disciple
Joined: 06 Aug 2011
Posts: 165
|
| fjb_saper wrote: |
| kotagiriaashish wrote: |
| Code: |
22:30:51.439387 4896.1 RSESS:000002 !! - MQPUT >>
22:30:52.928716 4896.1 RSESS:000002 !! - MQPUT <<
489 ms approx...
|
What do you think?? |
You mean to say: 1.489329 seconds for the put. What was the size of the message? |
100 bytes |
|
| Back to top |
|
|
| fjb_saper |
| Posted: Wed Jan 04, 2012 12:30 pm Post subject: |
|
|
Grand High Poobah
Joined: 18 Nov 2003
Posts: 20763
Location: LI,NY
|
100 bytes should not take much more than 4ms ... there is something else at play.
What type of queue was it put to? Is this a temporary dynamic reply to queue? Is it in Solaris Zones? Poor quality network? CPU maxed out? IO maxed out? Heavy paging?
_________________
MQ & Broker admin |
|
| Back to top |
|
|
| mqjeff |
| Posted: Wed Jan 04, 2012 12:40 pm Post subject: |
|
|
Grand Master
Joined: 25 Jun 2008
Posts: 17447
|
| kotagiriaashish wrote: |
| Code: |
22:30:51.439387 4896.1 RSESS:000002 !! - MQPUT >>
22:30:52.928716 4896.1 RSESS:000002 !! - MQPUT <<
489 ms approx...
|
What do you think?? |
Is that the first PUT, an average PUT, or the last PUT? |
|
| Back to top |
|
|
| kotagiriaashish |
| Posted: Wed Jan 04, 2012 12:44 pm Post subject: |
|
|
Disciple
Joined: 06 Aug 2011
Posts: 165
|
| mqjeff wrote: |
| kotagiriaashish wrote: |
| Code: |
22:30:51.439387 4896.1 RSESS:000002 !! - MQPUT >>
22:30:52.928716 4896.1 RSESS:000002 !! - MQPUT <<
489 ms approx...
|
What do you think?? |
Is that the first PUT, an average PUT, or the last PUT? |
there are more than 5000 such lines i just picked two puts...
| Code: |
First one
22:30:49.203128 4896.1 RSESS:000002 !! - MQPUT >>
22:30:49.499438 4896.1 RSESS:000002 !! - MQPUT <<
|
| Code: |
Last one
22:47:47.665308 4896.1 RSESS:000002 !! - MQPUT1 >>
22:47:47.948224 4896.1 RSESS:000002 !! - MQPUT1 <<
|
|
|
| Back to top |
|
|
| bruce2359 |
| Posted: Wed Jan 04, 2012 12:48 pm Post subject: |
|
|
Poobah
Joined: 05 Jan 2008
Posts: 9475
Location: US: west coast, almost. Otherwise, enroute.
|
Check a few here and there. (Quick REXX or similar script.) Is the time roughly the same? Any anomalies?
_________________
I like deadlines. I like to wave as they pass by.
ב''ה
Lex Orandi, Lex Credendi, Lex Vivendi. As we Worship, So we Believe, So we Live. |
|
| Back to top |
|
|
| kotagiriaashish |
| Posted: Wed Jan 04, 2012 12:51 pm Post subject: |
|
|
Disciple
Joined: 06 Aug 2011
Posts: 165
|
| bruce2359 wrote: |
| Check a few here and there. (Quick REXX or similar script.) Is the time roughly the same? Any anomalies? |
some take 20ms on avg and some take more than 50ms..
we did a ping from the client to the server it took 400+ ms .... will that help? |
|
| Back to top |
|
|
| Vitor |
| Posted: Wed Jan 04, 2012 12:51 pm Post subject: |
|
|
Grand High Poobah
Joined: 11 Nov 2005
Posts: 26093
Location: Texas, USA
|
I can't help noticing:
- the first one is using MQPUT, the last is using MQPUT1. That's an odd loop.
- the first one is timed at 22:30:49, the last timed at 22:47:47. Now I've had a fair amount of caffine today (for reasons unimportant in this context) but that doesn't seem to be 40 minutes apart to me.
_________________
Honesty is the best policy.
Insanity is the best defence. |
|
| Back to top |
|
|
| kotagiriaashish |
| Posted: Wed Jan 04, 2012 12:53 pm Post subject: |
|
|
Disciple
Joined: 06 Aug 2011
Posts: 165
|
| Vitor wrote: |
I can't help noticing:
- the first one is using MQPUT, the last is using MQPUT1. That's an odd loop.
- the first one is timed at 22:30:49, the last timed at 22:47:47. Now I've had a fair amount of caffine today (for reasons unimportant in this context) but that doesn't seem to be 40 minutes apart to me. |
I decreased the number of messages.... |
|
| Back to top |
|
|
| Vitor |
| Posted: Wed Jan 04, 2012 12:56 pm Post subject: |
|
|
Grand High Poobah
Joined: 11 Nov 2005
Posts: 26093
Location: Texas, USA
|
| kotagiriaashish wrote: |
| I decreased the number of messages.... |
You could have mentioned that.. 
But 50ms * 5000 messages isn't 40 minutes is it? And you said some only took 20ms.
_________________
Honesty is the best policy.
Insanity is the best defence. |
|
| Back to top |
|
|
| kotagiriaashish |
| Posted: Wed Jan 04, 2012 1:00 pm Post subject: |
|
|
Disciple
Joined: 06 Aug 2011
Posts: 165
|
| Vitor wrote: |
| kotagiriaashish wrote: |
| I decreased the number of messages.... |
You could have mentioned that..
But 50ms * 5000 messages isn't 40 minutes is it? And you said some only took 20ms. |
We did that calculation too with 24ms as avg it should have took only 1.2minutes but its taking 17 minutes...
((24*3000)/1000)/60) |
|
| Back to top |
|
|
| Vitor |
| Posted: Wed Jan 04, 2012 1:04 pm Post subject: |
|
|
Grand High Poobah
Joined: 11 Nov 2005
Posts: 26093
Location: Texas, USA
|
| kotagiriaashish wrote: |
We did that calculation too with 24ms as avg it should have took only 1.2minutes but its taking 17 minutes...
((24*3000)/1000)/60) |
This is at the heart of the problem. Either some of the put calls are taking significantly longer and you need to identify these (with REXX script or similar) or your method of determining that they have all arrived on the queue is flawed or there's another factor at work we've not identified.
You need to pin down where this extra time is coming from.
_________________
Honesty is the best policy.
Insanity is the best defence. |
|
| Back to top |
|
|
|
|
