lsquic icon indicating copy to clipboard operation
lsquic copied to clipboard
verified publisher icon litespeedtech

client stop sending data under presure testing?

Open emailsters opened this issue 3 years ago • 1 comments

Hello, I meet a strange problem causing the client stop sending packets when doing my program's presure testing.

the client side send 5760 bytes by lsquic_stream_write in on_write callback，the engine didn't schedule send packets out？the connection becomes not tickable.

2022-08-26 10:27:42.192 [DEBUG] engine: send_packets_out: sent 0 packets

Detail:

connection=3086627034087193389 quic engine can write
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: send_ctl_can_send: n_out: 0 (unacked_all: 0); cwnd: 5840
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: lsquic_pacer_can_schedule: 1
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: created packet 347876
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] event: created packet 347876; flags: version=0, nonce=0, conn_id=1
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: lsquic_pacer_packet_scheduled: replenish tokens: 10
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: lsquic_pacer_packet_scheduled: tokens: 9
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] event: generated STREAM frame: stream 0, offset: 497767170, size: 1440, fin: 0
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: send_ctl_can_send: n_out: 1472 (unacked_all: 0); cwnd: 5840
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: lsquic_pacer_can_schedule: 1
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: created packet 347877
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] event: created packet 347877; flags: version=0, nonce=0, conn_id=1
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: lsquic_pacer_packet_scheduled: tokens: 8
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] event: generated STREAM frame: stream 0, offset: 497768610, size: 1440, fin: 0
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: send_ctl_can_send: n_out: 2944 (unacked_all: 0); cwnd: 5840
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: lsquic_pacer_can_schedule: 1
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: created packet 347878
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] event: created packet 347878; flags: version=0, nonce=0, conn_id=1
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: lsquic_pacer_packet_scheduled: tokens: 7
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] event: generated STREAM frame: stream 0, offset: 497770050, size: 1440, fin: 0
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: send_ctl_can_send: n_out: 4416 (unacked_all: 0); cwnd: 5840
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: lsquic_pacer_can_schedule: 1
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: created packet 347879
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] event: created packet 347879; flags: version=0, nonce=0, conn_id=1
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: lsquic_pacer_packet_scheduled: tokens: 6
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] event: generated STREAM frame: stream 0, offset: 497771490, size: 1440, fin: 0
2022-08-26 10:27:42.191 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 0); cwnd: 5840
connection=3086627034087193389 write 5760 bytes to quic engine
2022-08-26 10:27:42.192 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 0); cwnd: 5840
2022-08-26 10:27:42.192 [DEBUG] engine: incref conn 2D7BE210EFE6D52A, 'H' -> 'HO'
2022-08-26 10:27:42.192 [DEBUG] engine: incref conn 2D7BE210EFE6D52A, 'HO' -> 'HOK'
2022-08-26 10:27:42.192 [DEBUG] engine: batched all outgoing packets for full conn 2D7BE210EFE6D52A
2022-08-26 10:27:42.192 [DEBUG] engine: decref conn 2D7BE210EFE6D52A, 'HOK' -> 'HK'
2022-08-26 10:27:42.192 [DEBUG] engine: send_packets_out: sent 0 packets
2022-08-26 10:27:42.192 [DEBUG] engine: decref conn 2D7BE210EFE6D52A, 'HK' -> 'H'
2022-08-26 10:27:42.192 [DEBUG] [QUIC:2D7BE210EFE6D52A] conn: not tickable
2022-08-26 10:27:42.192 [DEBUG] engine: incref conn 2D7BE210EFE6D52A, 'H' -> 'HA'
2022-08-26 10:27:42.192 [DEBUG] engine: next advisory tick is 192275 usec away: conn 2D7BE210EFE6D52A: PACK_TOL

And after this, it didn't send out packets any more, until the connection was closed by 'no progress timeout'.

I didn't find out the how it happen after reading the code.

Another strange thing, sometimes the pacer's next_sched wents wrong? 2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 18446744073709551252 usec from now

Detail:

connection=3086627034087193389 quic engine can write
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: send_ctl_can_send: n_out: 13248 (unacked_all: 13248); cwnd: 16436
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: lsquic_pacer_can_schedule: 1
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: created packet 346799
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] event: created packet 346799; flags: version=0, nonce=0, conn_id=1
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: making up: 1; app limited; 0
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 18446744073709551252 usec from now
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] event: generated STREAM frame: stream 0, offset: 496232491, size: 1439, fin: 0
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: send_ctl_can_send: n_out: 14720 (unacked_all: 13248); cwnd: 16436
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: lsquic_pacer_can_schedule: 1
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: created packet 346800
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] event: created packet 346800; flags: version=0, nonce=0, conn_id=1
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: making up: 1; app limited; 0
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 18446744073709551527 usec from now
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] event: generated STREAM frame: stream 0, offset: 496233930, size: 1439, fin: 0
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: send_ctl_can_send: n_out: 16192 (unacked_all: 13248); cwnd: 16436
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: lsquic_pacer_can_schedule: 1
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: created packet 346801
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] event: created packet 346801; flags: version=0, nonce=0, conn_id=1
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: making up: 0; app limited; 0
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 186 usec from now
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] event: generated STREAM frame: stream 0, offset: 496235369, size: 1439, fin: 0
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] sendctl: send_ctl_can_send: n_out: 17664 (unacked_all: 13248); cwnd: 16436
connection=3086627034087193389 write 4317 bytes to quic engine

after filter the log, it seems to be frequent. maybe it is related to stop sending packets?

2022-08-26 10:27:40.039 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 47 usec from now
2022-08-26 10:27:40.039 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 322 usec from now
2022-08-26 10:27:40.040 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 597 usec from now
2022-08-26 10:27:40.041 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 275 usec from now
2022-08-26 10:27:40.041 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 550 usec from now
2022-08-26 10:27:40.041 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 825 usec from now
2022-08-26 10:27:40.041 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 1100 usec from now
2022-08-26 10:27:40.044 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 275 usec from now
2022-08-26 10:27:40.044 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 550 usec from now
2022-08-26 10:27:40.044 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 825 usec from now
2022-08-26 10:27:40.044 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 1100 usec from now
2022-08-26 10:27:40.047 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 18446744073709549873 usec from now
2022-08-26 10:27:40.047 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 18446744073709550148 usec from now
2022-08-26 10:27:40.047 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 18446744073709550423 usec from now
2022-08-26 10:27:40.047 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 18446744073709550698 usec from now
2022-08-26 10:27:40.048 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 18446744073709549490 usec from now
2022-08-26 10:27:40.048 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 275 usec from now
2022-08-26 10:27:40.049 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 550 usec from now
2022-08-26 10:27:40.049 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 825 usec from now
2022-08-26 10:27:40.049 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 1100 usec from now
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 18446744073709551252 usec from now
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 18446744073709551527 usec from now
2022-08-26 10:27:40.050 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 186 usec from now
2022-08-26 10:27:40.055 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 220 usec from now
2022-08-26 10:27:40.055 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 440 usec from now
2022-08-26 10:27:40.115 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 297 usec from now
2022-08-26 10:27:40.124 [DEBUG] [QUIC:2D7BE210EFE6D52A] pacer: next_sched is set to 297 usec from now

and this is my code

// push data to buffer
int send_data_to_buffer(const char* data, size_t data_len) {
  LogDebug("connection=%" PRIu64 " write %zu bytes to buffer", connid_, data_len);
  if (data_len != 0) {
    if (wantwrite_ == false) {
      LogDebug("connection=%" PRIu64 " set wantwrite=1", connid_);
      lsquic_stream_wantwrite(stream_, 1);
      wantwrite_ = true;
    }
  }

  out_buffer_.Append(data, data_len);
  return 0;
}

// when on_write callback, write data in buffer to stream
int on_stream_writable_wrapper() {
  LogDebug("connection=%" PRIu64 " quic engine can write", connid_);
  ssize_t nwrite = lsquic_stream_write(stream_, out_buffer_.BeginPtr(), out_buffer_.Datalen());
  if (nwrite < 0) {
    LogError("connection=%" PRIu64 " lsquic_stream_write failed,retcode=%zd", connid_, nwrite);
    return -1;
  }
  LogDebug("connection=%" PRIu64 " write %zd bytes to quic engine", connid_, nwrite);

  out_buffer_.ForwardBegin(nwrite);
  out_buffer_.Recycle();

  if (out_buffer_.Datalen() == 0) {
    LogDebug("connection=%" PRIu64 " write all bytes=%zd done,flush stream", connid_, nwrite);
    lsquic_stream_flush(stream_);
    LogDebug("connection=%" PRIu64 " write all bytes=%zd done,set wantwrite=0", connid_, nwrite);
    if (wantwrite_ == true) {
      LogDebug("connection=%" PRIu64 " set wantwrite=0", connid_);
      lsquic_stream_wantwrite(stream_, 0);
      wantwrite_ = false;
    }
  }
  return 0;
}

emailsters avatar Aug 26 '22 09:08 emailsters

My test scenario is that the client sends one-way to the server, the client stop sending after a while.

if the server send something to client timely, it runs ok. the client can keep sending packets....

emailsters avatar Aug 29 '22 07:08 emailsters