send delays

[Steve Boynton]

I have a tasker task to send data to a IP2IR convertor. Everything works fine except, occasionally, the send is delayed or not executed.

I know the problem is not with tasker because I flash a message just before calling send/expect. I tap a button, I immediately see the flash, but sometimes the send is delayed or not sent. I can monitor send/expect output by the operation of the IP2IR convertor.

Any help would be greatly appreciated.

Thanks

[David]

The easiest thing to do first is enable Send/Expect logging.   It has relative timestamps in milliseconds for each of the interesting steps in its invocation life cycle.

This may tell you that the connect is taking a long time (e.g. is DNS involved and being pokey?), or that the connection is failing entirely.

But if the issue is with the latency between your task invoking Send/Expect and when Send/Expect actually runs, that may be a little harder to see.   There may be Tasker logging that you can enable to see this.

In the next version of Send/Expect (no current date yet for this) I will add a time/date timestamp to the beginning of the Send/Expect logging to help with correlations with Tasker logging.

[Steve Boynton]

Since the flash occurs immediately after I tap a button, I don't think it's Tasker.  Once I see the flash, there can be a very noticeable delay until I see the results via the IP2IR, if I see a result at all.  Tasker logging supports this.

I tablet is used only for home automation.  It has been set up to run a minimal amount of apps in order to keep the wifi open (i.e. no weather or game apps).

DNS is not involved.  All sends and expects occur on a LAN with addressing directly to the local IP address of the IP2IR.

I have added timer actions to the send/expect task.  A variable is set to the current time, the call to send/expect is performed and then the elapsed time is calculated and flashed.  The shortest time I ever see is about 150ms which is great.  However, quite often the elapsed time is 4 seconds or more.  I just set this up last night and so far I have not seen a send/expect completely skipped.

Thanks

[David]

Is your Tasker action timeout for Send/Expect set to a non-zero value larger than the Send/Expect timeout (see SendExpect FAQ) ?

If you capture an interesting Send/Expect log for an extra long latency, or a failed invocation, post it here, along with a good invocation example.

[Steve Boynton]

Yes.

OK, I'll try.

[Steve Boynton]

Just bumping this.  This continues to be a problem.  Do you have no other users with this issue?

Invocation is just too big so I'll describe it.  (Do you really need a log for me to prove what I'm saying?)

I am using send/expect with Tasker to control my entertainment system.  Each button on a Tasker screen has a 'perform task' action under the 'tap' tab.  Each of these tasks contains an IR code which is used as an arg to call the 's/e task'.  The s/e task uses the s/e plugin to send the arg to the IP2IR converter.

I have verified that my tasks are not bumping into each other, priority-wise.

I have logged with Tasker and as I described above, the log shows that the interface between s/e and the OS is where the delay occurs.  The s/e plugin action is called and a seemingly random delay occurs before the action returns and flashes the elapsed time.

Being a programmer myself, if I were to guess I'd say this is some sort of queueing issue.  I think another plugin, AutoRemote has the same issue.

Sony Experia Z tab

[David]

On Thursday, August 27, 2015 at 7:18:51 AM UTC-7, Steve Boynton wrote:

Just bumping this.  This continues to be a problem.  Do you have no other users with this issue?

Not that I know of.

 

Invocation is just too big so I'll describe it.  (Do you really need a log for me to prove what I'm saying?)

That isn't the point of the log.  If you send me a Send/Expect log it will show timestamps for each of the steps that Send/Expect took.  Long pauses would be easily identifiable in a particular portion of the Send/Expect execution.

I have logged with Tasker and as I described above, the log shows that the interface between s/e and the OS is where the delay occurs.  The s/e plugin action is called and a seemingly random delay occurs before the action returns and flashes the elapsed time.

Can you reproduce the same behavior with standalone Send/Exepct?  From Tasker, editing your Send/Expect configuration, you can save a named profile within Send/Expect, that you can then try to execute standalone.

 

Or if that isn't practical, just enable the Send/Expect logging and share a Send/Expect log for a Tasker invoked problem run.

[Steve Boynton]

Finally got this done.  Sorry it took so long.  This is one of the shorter delays.  I've experienced 5-10 second delays.  HTH, thanks.

[
  {
    "timestamp": 0,
    "recordType": "Start",
    "recordData": "Tasker"
  },
  {
    "timestamp": 0,
    "recordType": "Version",
    "recordData": "2000031"
  },
  {
    "timestamp": 0,
    "recordType": "Send/Expect Data",
    "recordData": "Timeout seconds: 5\nSend (original): sendir,1:2,1,38461,1,1,343,171,19,86,19,172,19,86,19,172,19,172,19,172,19,86,19,86,19,86,19,86,19,86,19,86,19,172,19,172,19,86,19,86,19,3846,\\r,\\n\nSend (variables replaced): sendir,1:2,1,38461,1,1,343,171,19,86,19,172,19,86,19,172,19,172,19,172,19,86,19,86,19,86,19,86,19,86,19,86,19,172,19,172,19,86,19,86,19,3846,\\r,\\n\nExpect: (?<tmp>.+)\n"
  },
  {
    "timestamp": 1005,
    "recordType": "Connection",
    "recordData": "192.168.0.9:4998"
  },
  {
    "timestamp": 1005,
    "recordType": "Send",
    "recordData": "sendir,1:2,1,38461,1,1,343,171,19,86,19,172,19,86,19,172,19,172,19,172,19,86,19,86,19,86,19,86,19,86,19,86,19,172,19,172,19,86,19,86,19,3846,\\r,\\n"
  },
  {
    "timestamp": 1007,
    "recordType": "Expect",
    "recordData": "(.+)"
  },
  {
    "timestamp": 1007,
    "recordType": "Received Buffer Contains",
    "recordData": ""
  },
  {
    "timestamp": 2817,
    "recordType": "Received Bytes",
    "recordData": "17"
  },
  {
    "timestamp": 2817,
    "recordType": "Received Buffer Contains",
    "recordData": "completeir,1:2,1\r"
  },
  {
    "timestamp": 2818,
    "recordType": "Expect Matched",
    "recordData": "completeir,1:2,1"
  },
  {
    "timestamp": 2818,
    "recordType": "Capture Group",
    "recordData": "tmpmatched completeir,1:2,1"
  },
  {
    "timestamp": 2818,
    "recordType": "Disconnect",
    "recordData": null
  },
  {
    "timestamp": 2819,
    "recordType": "Set Tasker Variable",
    "recordData": "%tmp = completeir,1:2,1"
  },
  {
    "timestamp": 2819,
    "recordType": "Succeeded",
    "recordData": null
  }
]

[David]

The timestamps are in milliseconds of elapsed time from the invocation of Send/Expect.

On Monday, August 31, 2015 at 3:53:05 AM UTC-7, technogeezer wrote:

[
  {
    "timestamp": 0,
    "recordType": "Start",
    "recordData": "Tasker"
  },

Initial invocation.

 

  {
    "timestamp": 0,
    "recordType": "Version",
    "recordData": "2000031"
  },
  {
    "timestamp": 0,
    "recordType": "Send/Expect Data",
    "recordData": "Timeout seconds: 5\nSend (original): sendir,1:2,1,38461,1,1,343,171,19,86,19,172,19,86,19,172,19,172,19,172,19,86,19,86,19,86,19,86,19,86,19,86,19,172,19,172,19,86,19,86,19,3846,\\r,\\n\nSend (variables replaced): sendir,1:2,1,38461,1,1,343,171,19,86,19,172,19,86,19,172,19,172,19,172,19,86,19,86,19,86,19,86,19,86,19,86,19,172,19,172,19,86,19,86,19,3846,\\r,\\n\nExpect: (?<tmp>.+)\n"
  },

Also at invocation time, the entire Send/Expect profile is traced.  After this trace event is generated, the connection is initiated:

        try
        {
            serverAddress = InetAddress.getByName(mHost);
            socketAddress = new InetSocketAddress(serverAddress, mPort);
            mSocket = new Socket();
            mSocket.setTcpNoDelay(true);
            mSocket.connect(socketAddress, getRemainingTimeout());
        }

 Given that your target address is an IP address, I would expect no DNS delay.

  {
    "timestamp": 1005,
    "recordType": "Connection",
    "recordData": "192.168.0.9:4998"
  },

A second later the connect returns.  My first expectation would be that this delay occurred on the listener side.  To see harder evidence for this, I suggest using a tool like Wireshark to track when the connect was issued and when it was accepted. 

 

  {
    "timestamp": 1005,
    "recordType": "Send",
    "recordData": "sendir,1:2,1,38461,1,1,343,171,19,86,19,172,19,86,19,172,19,172,19,172,19,86,19,86,19,86,19,86,19,86,19,86,19,172,19,172,19,86,19,86,19,3846,\\r,\\n"
  },

Immediately after the connection returns, the send data is sent.

 

  {
    "timestamp": 1007,
    "recordType": "Expect",
    "recordData": "(.+)"
  },

Next, SendExpect starts processing the expect statement in your profile.  2 milliseconds are used compiling the regular expression and setting up for the read. 

2 milliseconds after the send data is sent, SendExpect enters issues a read, waiting for the expect data:

  {
    "timestamp": 1007,
    "recordType": "Received Buffer Contains",
    "recordData": ""
  },

A loop is entered, which will wait for either a timeout or a hit on the regular expression.  Since there is no data yet in the receive buffer, a read is issued:

            try
            {
                mSocket.setSoTimeout(getRemainingTimeout());
                numRead = inputStream.read(bytes);
            }

 

  {
    "timestamp": 2817,
    "recordType": "Received Bytes",
    "recordData": "17"
  },

1.8 seconds later the data comes back.  My first expectation here is that this delay was due to processing on the other side of the connection.  Again, Wireshare could prove that.

 

  {
    "timestamp": 2817,
    "recordType": "Received Buffer Contains",
    "recordData": "completeir,1:2,1\r"
  },
  {
    "timestamp": 2818,
    "recordType": "Expect Matched",
    "recordData": "completeir,1:2,1"
  },

And the expect pattern is satisfied.

 

  {
    "timestamp": 2818,
    "recordType": "Capture Group",
    "recordData": "tmpmatched completeir,1:2,1"
  },

1 millsecond later final processing on the SendExpect profile is done.

 

  {
    "timestamp": 2818,
    "recordType": "Disconnect",
    "recordData": null
  },

The network connection is closed.

 

  {
    "timestamp": 2819,
    "recordType": "Set Tasker Variable",
    "recordData": "%tmp = completeir,1:2,1"
  },

Another millisecond and tasker variable substitution is done.  Though for this case, SendExpect probably shouldn't bother, as it wasn't invoked by Tasker this time.

 

  {
    "timestamp": 2819,
    "recordType": "Succeeded",
    "recordData": null
  }
]

SendExpect is complete.  2 milliseconds after the data returned. 

[technogeezer]

Wow, if only I had the time to learn wireshark.

The listener is an IP2IR converter which, when I talk to it through other TCP apps, has no delay.

In other words, the delay occurs only when using send/expect.

[David]

The Send/Expect log you posted, and I annotated, shows what appear to be delays occurring outside of Send/Expect (the connect call, and waiting for a response to the data sent).  I would not rule out the possibility of some unexpected behavior within Send/Expect and/or its interaction with the Android kernel, but it does not seem to be the most likely culprit given the data presented here.

I suggested Wireshark (a mature, well documented and free network sniffer) as a next step in isolating where the delays are occurring.  A sniffer could show the connect packet being sent from Send/Expect, and the response from the listener accepting, the send data being sent from Send/Expect and the expect data returning from the device.  Where the delays were occurring from a client / server point of view would be readily apparent.

[technogeezer]

From the log and your annotations I do not see how you can exclude anything.

I experimented with send/expect as a standalone app, sending the exact same message as above and I was able to reproduce the delay.  Again, the extended delay was randomly distributed between the connection and the data transfer steps.

Other apps sending the exact same message show no long delays, always completing within 200ms.

WS and sniffers can not provide information about the interface between send/expect and Tasker or the interface between Tasker and Android.

[David]

I've just released a new version of Send/Expect that adds two additional trace points in the log; when the connection request is made and when sending data returns from flushing the socket.  A log (or set of logs) showing delays and including these new traces would shed additional light on whether or not the delays are occurring within Send/Expect. 

Are the delays randomly distributed among a set of runs?  Or do they occur within the first of a set of runs that are done with some idle interval in between?

Is a single device that is seeing the delays?

Are you using any power saving mode with your network interfaces (e.g. putting WiFi in a standby or powered down mode when idle)?

Is there memory or processing contention on the device(s) where the delays are seen?

[technogeezer]

Hi David,

In order,

* Delays are completely random within my ability to test them.

* Delay occurs on a Sony Xperia Z (V1) tablet and an LG Optimus G Pro smart phone.

* Idle mode powers down the tablet and phone.

* On the tablet/phone, there's Android.  The other end is a Global Cache WIFI IP2IR, made to process TCP commands into IR bursts for controlling home entertainment equipment, etc.  In between is the tablet's WIFI to the router and then WIFI from the router to the IP2IR.

I won't be able to look at the logging until I get home tonight but I wanted to acknowledge your effort - thanks!

Thanks so much,
Steve

[technogeezer]

I looked at this many times since my last post.  I've also tried changing WIFI channels, testing S/E standalone (same result) and writing custom routines in Eclipse.  It still appears there's a problem either between Send/Expect and Tasker or between Tasker and Android's WIFI routines.

I don't know what else I can do.

[David]

On Tuesday, October 6, 2015 at 11:30:47 AM UTC-7, technogeezer wrote:

I looked at this many times since my last post.  I've also tried changing WIFI channels, testing S/E standalone (same result) and writing custom routines in Eclipse.  It still appears there's a problem either between Send/Expect and Tasker or between Tasker and Android's WIFI routines.

I don't know what else I can do.

Can you post or send me a couple of standalone Send/Expect debug logs from "bad" runs?   In the latest version of Send/Expect (2.0.4) there were a couple of new debug trace points added.