nginx introduces extra delay when talking to slow backend (probably FreeBSD kevent specific)

[Dmitry Marakasov]

* Dmitry Marakasov (amdmi3 at amdmi3.ru) wrote:

I've gathered ktrace dumps for both cases, and it really looks that
the problem is related to kevent. After nginx sends response back
to client, it calls kevent(2) on client fd (which is 5).

When there is a bug (FreeBSD 11.2), the following happens:

 49365 nginx    3.099362 CALL  kevent(0x7,0x8022a2000,0,0x8023005c0,0x200,0x7fffffffe598)
 49365 nginx    3.099419 STRU  struct kevent[] = {  }
 49365 nginx    3.194695 STRU  struct kevent[] = { { ident=5, filter=EVFILT_WRITE, flags=0x20<EV_CLEAR>, fflags=0, data=0xbf88, udata=0x8023633d1 } }
 49365 nginx    3.194733 RET   kevent 1
...
 49365 nginx    3.194858 CALL  kevent(0x7,0x8022a2000,0,0x8023005c0,0x200,0x7fffffffe598)
 49365 nginx    3.194875 STRU  struct kevent[] = {  }
 49365 nginx    3.835259 STRU  struct kevent[] = { { ident=5, filter=EVFILT_READ, flags=0x8020<EV_CLEAR|EV_EOF>, fflags=0, data=0, udata=0x802346111 } }
 49365 nginx    3.835299 RET   kevent 1

E.g. read and write events come separately, both with huge delays.

On FreeBSD-CURRENT which doesn't experience the problem, kdump looks this way:

  8049 nginx    3.081367 CALL  kevent(0x7,0x8012d1b40,0,0x8012da040,0x200,0x7fffffffe598)
  8049 nginx    3.081371 STRU  struct kevent[] = {  }
  8049 nginx    3.081492 STRU  struct kevent[] = { { ident=5, filter=EVFILT_WRITE, flags=0x20<EV_CLEAR>, fflags=0, data=0xbf88, udata=0x801341f11 }
             { ident=5, filter=EVFILT_READ, flags=0x8020<EV_CLEAR|EV_EOF>, fflags=0, data=0, udata=0x801324e51 } }
  8049 nginx    3.081498 RET   kevent 2

E.g. both events come immediately and at the same time.

Not sure if that's problem of kevent or something it relies on or the
way nginx uses it.

-- 
Dmitry Marakasov   .   55B5 0596 FF1E 8D84 5F56  9510 D35A 80DD F9D2 F77D
amdmi3 at amdmi3.ru  ..:              https://github.com/AMDmi3