REST SSE events stream delayed

[RyanRamchandar]

What was expected: The SSE event stream at /rest/events/ should emit events in a timely fashion (within 100ms) from the time an action triggers that event, ie. REST calls posting commands/state to Items, adding/removing Things, etc.

What happens instead: There is a noticeable, unpredictable, delay between doing an action and the event emitted from the SSE stream. This delay can range from nearly instantaneous <100ms upwards to 30 seconds or more.

Steps to reproduce: I have not found a repeatable way to reproduce the delay though it occurs frequently enough to be an issue. That being said, I was able to exhibit the delay using ApacheBench (tool used to benchmark REST APIs).

I performed a test (admittedly extreme) of sending 10,000 POST requests from 32 concurrent threads: $ ab -p POST -T text/plain -c 32 -n 10000 http://192.168.1.200:8080/rest/items/thing_442c052dc972_switch1

Where POST is a file that has the text ON.

The command took about 3 min to complete and gave these results:

Server Software:        Jetty(9.2.19.v20160908)
Server Hostname:        192.168.1.200
Server Port:            8080

Document Path:          /rest/items/thing_442c052dc972_switch1
Document Length:        0 bytes

Concurrency Level:      32
Time taken for tests:   193.550 seconds
Complete requests:      10000
Failed requests:        0
Total transferred:      1340000 bytes
Total body sent:        1860000
HTML transferred:       0 bytes
Requests per second:    51.67 [#/sec] (mean)
Time per request:       619.359 [ms] (mean)
Time per request:       19.355 [ms] (mean, across all concurrent requests)
Transfer rate:          6.76 [Kbytes/sec] received
                        9.38 kb/s sent
                        16.15 kb/s total

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        1    3  13.2      2     474
Processing:     8  612 963.7    260    6525
Waiting:        8  612 963.7    260    6525
Total:         10  615 964.4    263    6526

Percentage of the requests served within a certain time (ms)
  50%    263
  66%    461
  75%    667
  80%    800
  90%   1534
  95%   2428
  98%   4423
  99%   4894
 100%   6526 (longest request)

I then observed the event stream at /rest/events and saw that 1000's of ItemCommandEvents and ItemStateEvent were still happening. This continues on for more than 10 minutes afterwards.

Background: We have custom devices that POST commands to Items, eg. Switch Item ON, and listens to the SSE stream at /rest/events for ItemCommandEvents. A appropriate device listens to the event stream and acts on ItemCommandEvent that they care about and turn on their switch.

Some observations:

• sending multiple REST requests to openHAB increases the chance of a delay in the event stream
• when openHAB has been idle for a while (more than an hour) the chance for a delay is increased
• events can take much longer to arrive then the rest response takes to complete. The events appear to be queued.
• the event stream often time seems to be “stuck”. And performing a REST call like GET things flushes the event stream

openHAB setup: openHAB2 is the 2.0.0 release running on a Pine64 (we have also tested on a MacBook Pro 2015 but the same delay is exhibited)

[kaikreuzer]

Did you do any analysis on WHERE this delay might be introduced? I.e. at which moment is it logged in the runtime? I probably would make sense to break your tests into two parts:

1. Send HTTP POST requests to items and check how long it takes for the changes to appear in the log file.
2. Send commands on the local console and check how long it takes until they are broadcasted via SSE.

[NJQter]

I encountered the same problem. However, when the first connect is reached, the message is immediate. Message delay occurred after a period of time.