BUG: Is the serial port blocking the webserver?

[moelski]

Hi @all,

today I installed a SOnOff with ESPEasy R136. It´s just a plain R136 compilation with the switch input and 2 system information tasks.
I included the SonOff to my FHEM setup and just call http://192.168.xxx.xxx/control?cmd=GPIO,12,0|1 to switch the relais on or off.
This works - mostly.

After some time I figured out that the response was very slow - sometimes more than 9 seconds

So I run Fiddler to check the request / response time. See the first picture where everthing is ok. The response time is around 30-40 milliseconds.
At the second picture the serial port is enabled in the advanced settings. And from time to time the communication hangs

There are response times from over 9 seconds. And that results in a timeout

So can anyone of the devs check if there is something blocking on the serial part? I should mention that the serial port is not connected to a computer during this test.
But I have never had such a problem before.

[Martinus]

I'm using this little VB script to verify webrequests:

Code: Select all

ip = WScript.Arguments.Item(0)

Set objFSO = CreateObject("Scripting.FileSystemObject")
Set objLogFile = objFSO.createTextFile("webtestlog_" & ip & ".txt", True)

count=0                  ' count number of requests
errors=0                 ' count request with returncode <> 200
min=10000                ' keep track of fastest response
max=0                    ' keep track of slowest response
onesecond=0              ' count number of requests beyond one second response time
total=0                  ' count total time
state=1                  ' track gpio toggle state

do while true
  if state =1 then
    state = 0
  else
    state = 1
  end if
  Set objHTTP = CreateObject( "WinHttp.WinHttpRequest.5.1" )
  objHTTP.Open "GET", "http://" & ip & "/control?cmd=gpio,2," & state, False
  objHTTP.SetRequestHeader "User-Agent", "Mozilla/4.0 (compatible; MyApp 1.0; Windows NT 5.1)"

  on error resume next
  start = timer()
  objHTTP.Send
  duration = (timer()-start) * 1000
  intStatus = objHTTP.Status
  Set objHTTP = Nothing
  on error goto 0
  
  if intStatus = 200 then
    count = count + 1
    total = total + duration
    if duration > 1000 then
      onesecond = onesecond + 1
    end if
    if duration > max then
      max = duration
    end if
    if duration < min then
      min = duration
    end if
    logging = "Cnt:" & count & "  Dur:" & round(duration) & "mS  Min:" & round(min) & "mS  Max:" & round(max) & "mS  Avg:" & round(total/count) & "mS  >1s:" & round(onesecond) & "  Err:" & round(errors)
  else
    errors = errors + 1
    logging = "Errors: " & errors
  end if
  Wscript.echo logging
  objLogFile.writeline(logging)
  Wscript.sleep 1000
loop

It toggles GPIO2 on and off using http requests. I let it run for about 10 minutes on my Sonoff device with serial and weblogging both set to level 2. Last part of the logfile:

Code: Select all

Cnt:606  Dur:94mS  Min:62mS  Max:2098mS  Avg:93mS  >1s:4  Err:0
Cnt:607  Dur:98mS  Min:62mS  Max:2098mS  Avg:93mS  >1s:4  Err:0
Cnt:608  Dur:98mS  Min:62mS  Max:2098mS  Avg:93mS  >1s:4  Err:0
Cnt:609  Dur:90mS  Min:62mS  Max:2098mS  Avg:93mS  >1s:4  Err:0
Cnt:610  Dur:82mS  Min:62mS  Max:2098mS  Avg:93mS  >1s:4  Err:0
Cnt:611  Dur:86mS  Min:62mS  Max:2098mS  Avg:93mS  >1s:4  Err:0
Cnt:612  Dur:78mS  Min:62mS  Max:2098mS  Avg:93mS  >1s:4  Err:0
Cnt:613  Dur:74mS  Min:62mS  Max:2098mS  Avg:93mS  >1s:4  Err:0
Cnt:614  Dur:102mS  Min:62mS  Max:2098mS  Avg:93mS  >1s:4  Err:0
Cnt:615  Dur:94mS  Min:62mS  Max:2098mS  Avg:93mS  >1s:4  Err:0
Cnt:616  Dur:82mS  Min:62mS  Max:2098mS  Avg:93mS  >1s:4  Err:0
Cnt:617  Dur:86mS  Min:62mS  Max:2098mS  Avg:93mS  >1s:4  Err:0
Cnt:618  Dur:148mS  Min:62mS  Max:2098mS  Avg:93mS  >1s:4  Err:0
Cnt:619  Dur:82mS  Min:62mS  Max:2098mS  Avg:93mS  >1s:4  Err:0
Cnt:620  Dur:74mS  Min:62mS  Max:2098mS  Avg:93mS  >1s:4  Err:0
Cnt:621  Dur:94mS  Min:62mS  Max:2098mS  Avg:93mS  >1s:4  Err:0

More than 600 requests fired, one request per second, no errors, average response 93 milliSeconds and maximum 2098 mSeconds.
4 requests took longer than 1 second.
Sonoff runs R140

[moelski]

Hi Martinus,

this is strange
I will try the latest Github version today and test if it works better ...

[moelski]

Hi Martinus,

I flashed the 141 today and at first it looks ok. But ofter some tests it seems that the problem still exists.
This is what I did:
* Compile & Flash R141
* Enable Web and Serial Logging
* Set Loglevel serial to 2 (Default)
At this stage everthing seems to be ok.

But after setting the serial Loglevel to 4 there are sometimes delays if you toggle the Output relais of the SonOff very fast.

It seems a little bit better than the test with R136. But anyway ... Looks like to serial Output generates some delay.

I wasn´t able to reproduce these really long delays from ~9 seconds like in my initial posting.
But maybe you can give it a try with loglevel 4 on serial Log.