Async submit taking more time even when window is not full

[abin-mathew]

This is a continuation of issue #77

I have noticed that my sms service slows down under high traffic. I am using async submit, and to debug this I have added a log to print the time taken to do an async submit including window stats. From the log I can see that the time taken for async submit increases gradually from about 2 millisec to almost 400 millisecs even when the window is nowhere near full. Logs added in code is :

long start = Calendar.getInstance().getTimeInMillis();
session.sendRequestPdu(submit, 30000, false);
long end = Calendar.getInstance().getTimeInMillis();
long timeTaken = end - start;
log.info("Window data. max size : "+window.getMaxSize()+" size : "+window.getSize()+" free : "+window.getFreeSize()+" pending : "+ window.getPendingOfferCount()+" session : "+zdSession.getName()+" time : "+timeTaken);

The logs printed for a single session at three points during the execution are

12:32:30.618[DEBUG][taskExecutor-23] [smpp] [ZdAsyncMessageSender.java:97] - Window data. max size : 50 size : 1 free : 49 pending : 0 session : Account_2000140116_36 time : 24

12:32:31.649[DEBUG][taskExecutor-43] [smpp] [ZdAsyncMessageSender.java:97] - Window data. max size : 50 size : 3 free : 47 pending : 0 session : Account_2000140116_36 time : 133

12:32:33.850[DEBUG][taskExecutor-44] [smpp] [ZdAsyncMessageSender.java:97] - Window data. max size : 50 size : 3 free : 47 pending : 0 session : Account_2000140116_36 time : 461

From the log it appears that even when the window is not full the async submit time gradually increases. Under what situation can this happen? Does it by any chance depend on the SMSC speed? Is there anything else that I am missing?

[jjlauer]

Can you log the window stat before AND after the sendRequestPdu call?

Is this against a real SMSC or a simulator?

On Thu, Feb 26, 2015 at 3:09 AM, abin-mathew [email protected]
wrote:

This is a continuation of issue #77
#77

I have noticed that my sms service slows down under high traffic. I am
using async submit, and to debug this I have added a log to print the time
taken to do an async submit including window stats. From the log I can see
that the time taken for async submit increases gradually from about 2
millisec to almost 400 millisecs even when the window is nowhere near full.
Logs added in code is :

long start = Calendar.getInstance().getTimeInMillis();
session.sendRequestPdu(submit, 30000, false);
long end = Calendar.getInstance().getTimeInMillis();
long timeTaken = end - start;
log.info("Window data. max size : "+window.getMaxSize()+" size :
"+window.getSize()+" free : "+window.getFreeSize()+" pending : "+
window.getPendingOfferCount()+" session : "+zdSession.getName()+" time :
"+timeTaken);

The logs printed for a single session at three points during the execution
are

12:32:30.618[DEBUG][taskExecutor-23] [smpp] [ZdAsyncMessageSender.java:97]

• Window data. max size : 50 size : 1 free : 49 pending : 0 session :
  Account_2000140116_36 time : 24

12:32:31.649[DEBUG][taskExecutor-43] [smpp] [ZdAsyncMessageSender.java:97]

• Window data. max size : 50 size : 3 free : 47 pending : 0 session :
  Account_2000140116_36 time : 133

12:32:33.850[DEBUG][taskExecutor-44] [smpp] [ZdAsyncMessageSender.java:97]

• Window data. max size : 50 size : 3 free : 47 pending : 0 session :
  Account_2000140116_36 time : 461

From the log it appears that even when the window is not full the async
submit time gradually increases. Under what situation can this happen? Does
it by any chance depend on the SMSC speed? Is there anything else that I am
missing?

—
Reply to this email directly or view it on GitHub
#82.

[abin-mathew]

This is a real SMSC. We have asked them to not submit messages to operator until we are done with load testing. Will the SMSC response time affect the time taken by async submit?

I have added the following to print window stats before and after submit :

log.info("Window data before submit. max size : "+window.getMaxSize()+", size : "+window.getSize()+", free : "+window.getFreeSize()+", pending : "+window.getPendingOfferCount()+", session : "+zdSession.getName());
session.sendRequestPdu(submit, 30000, false);
log.info("Window data. max size : "+window.getMaxSize()+", size : "+window.getSize()+", free : "+window.getFreeSize()+", pending : "+window.getPendingOfferCount()+", session : "+zdSession.getName()+", time : "+timeTaken);

The logs printed were :

11:15:18.160[ INFO][taskExecutor-58] [smpp] [ZdAsyncMessageSender.java:101] - Window data before submit. max size : 50, size : 1, free : 49, pending : 0, session : Account_2000140116_29
11:15:18.160[ INFO][taskExecutor-69] [smpp] [ZdAsyncMessageSender.java:101] - Window data before submit. max size : 50, size : 0, free : 50, pending : 0, session : Account_2000140116_27

11:15:18.255[ INFO][taskExecutor-69] [smpp] [ZdAsyncMessageSender.java:121] - Window data. max size : 50, size : 1, free : 49, pending : 0, session : Account_2000140116_27, time : 95
11:15:18.278[ INFO][taskExecutor-58] [smpp] [ZdAsyncMessageSender.java:121] - Window data. max size : 50, size : 1, free : 49, pending : 0, session : Account_2000140116_29, time : 118

[jjlauer]

If async mode is on -- then here are reasons the method may block/take time:

1. The underlying window is full and it needs to wait for a slot to open
   up. In your case it looks like you picked 50 slots. If you send a message
   every 2 ms and your smsc actually takes 400 ms to respond -- then you do
   the math -- eventually you will fill up all your 50 slots. Thus, using the
   example of 400 ms, then sendRequestPdu will take about 400 ms of time.
   SMSCs do not offer unlimited capacity or throughput. The "window" is just
   a way of making transmission somewhat better over the Internet.
2. If the underlying window is not full, then there are still parts of
   sendRequestPdu that may block a bit. One place is writing the packet onto
   the socket/channel. There may be more and you'll probably learn quite a
   bit if you start in the source and work your way through sendRequestPdu and
   see exactly what it does.

I'd also suggest isolating out parts of your code to do more profiling.
Maybe its your test rig. Maybe its the SMSC. There is a fake server with
this library -- have you tried running your code against that to see if it
behaves the same way?

If you are still hitting an issue figuring this out -- and if you have the
budget you can always consider having the consulting company I run, Fizzed,
actually dig into your code.

On Thu, Feb 26, 2015 at 10:14 PM, abin-mathew [email protected]
wrote:

This is a real SMSC. We have asked them to not submit messages to operator
until we are done with load testing. Will the SMSC response time affect the
time taken by async submit?

I have added the following to print window stats before and after submit :

log.info("Window data before submit. max size : "+window.getMaxSize()+",
size : "+window.getSize()+", free : "+window.getFreeSize()+", pending :
"+window.getPendingOfferCount()+", session : "+zdSession.getName());
session.sendRequestPdu(submit, 30000, false);
log.info("Window data. max size : "+window.getMaxSize()+", size :
"+window.getSize()+", free : "+window.getFreeSize()+", pending :
"+window.getPendingOfferCount()+", session : "+zdSession.getName()+", time
: "+timeTaken);

The logs printed were :

11:15:18.160[ INFO][taskExecutor-58] [smpp]
[ZdAsyncMessageSender.java:101] - Window data before submit. max size : 50,
size : 1, free : 49, pending : 0, session : Account_2000140116_29
11:15:18.160[ INFO][taskExecutor-69] [smpp]
[ZdAsyncMessageSender.java:101] - Window data before submit. max size : 50,
size : 0, free : 50, pending : 0, session : Account_2000140116_27

11:15:18.255[ INFO][taskExecutor-69] [smpp]
[ZdAsyncMessageSender.java:121] - Window data. max size : 50, size : 1,
free : 49, pending : 0, session : Account_2000140116_27, time : 95
11:15:18.278[ INFO][taskExecutor-58] [smpp]
[ZdAsyncMessageSender.java:121] - Window data. max size : 50, size : 1,
free : 49, pending : 0, session : Account_2000140116_29, time : 118

—
Reply to this email directly or view it on GitHub
#82 (comment)
.