Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Issue with streams throughput fairness #467

Open
mickael-cerisier opened this issue Jun 6, 2023 · 4 comments
Open

Issue with streams throughput fairness #467

mickael-cerisier opened this issue Jun 6, 2023 · 4 comments

Comments

@mickael-cerisier
Copy link
Contributor

mickael-cerisier commented Jun 6, 2023

Hi,

I work on a new network layer for our products based on lsquic and libuv. In our product each thread use its own quic stream, so there is one connection with N quic stream. I only use the quic layer, I don't use HTTP3.
My problem is pretty simple, if I write lot of data on multiple streams, only one stream has access to the throughput, the others wait that it finished. All streams have the same priority.

I analyse the source code of lsquic but I don't know how to fix.

lsquic_stream.c:2442
there is a code that puts the stream at the end of the list, this part works.

if (stream->sm_qflags & SMQF_WRITE_Q_FLAGS)
{
    if (progress)
    {   /* Move the stream to the end of the list to ensure fairness. */
        TAILQ_REMOVE(&stream->conn_pub->write_streams, stream,
                                                        next_write_stream);
        TAILQ_INSERT_TAIL(&stream->conn_pub->write_streams, stream,
                                                        next_write_stream);
    }
}

lsquic_hpi.c:313
inside calc_next_prio_and_incr my hpi_set[0] is always equal to [4,0] with stream priority set to 255
Values are always same, prio=2 and incr=0 so I go inside next_nonincr.

struct lsquic_stream *
lsquic_hpi_next (void *iter_p)
{
    struct http_prio_iter *const iter = iter_p;
    struct lsquic_stream *stream;
    unsigned prio, incr;

    calc_next_prio_and_incr(iter, prio, incr);

    if (prio >= N_HPI_PRIORITIES)
        return NULL;

    if (incr)
        stream = next_incr(iter, prio);
    else
        stream = next_nonincr(iter, prio);

    if (LSQ_LOG_ENABLED(LSQ_LOG_DEBUG))
        HPI_DEBUG("%s: return stream %"PRIu64", incr: %u, priority %u",
                                            __func__, stream->id, incr, prio);
    return stream;
}

lsquic_hpi.c:275
Inside next_nonincr, I go

  1. else if (iter->hpi_counts[prio] > 1) line 289
  2. if (0 == heap_nonincr_bucket(iter, prio))
  3. goto pop_stream
  4. stream = lsquic_mh_pop(&iter->hpi_min_heap);

At the end, lsquic use the method heapify_min_heap that ignore the list order, but search for the smallest stream id.

my call stack:

heapify_min_heap(min_heap * heap, unsigned int i) at lsquic_min_heap.c(15)
lsquic_mh_pop(min_heap * heap) at lsquic_min_heap.c(86)
next_nonincr(http_prio_iter * iter, unsigned int prio) at lsquic_hpi.c(282)
lsquic_hpi_next(void * iter_p) at lsquic_hpi.c(327)
lsquic_hpi_first(void * iter_p) at lsquic_hpi.c(184)
process_streams_write_events(ietf_full_conn * conn, int high_prio) at lsquic_full_conn_ietf.c(4461)
ietf_full_conn_ci_tick(lsquic_conn * lconn, unsigned __int64 now) at lsquic_full_conn_ietf.c(8529)
process_connections(lsquic_engine * engine, lsquic_conn *(*)(lsquic_engine *) next_conn, unsigned __int64 now) at lsquic_engine.c(3055)
lsquic_engine_process_conns(lsquic_engine * engine) at lsquic_engine.c(2242)

I tested changing the priority of the stream to 4, 5 before realizing that the order is reversed when it's not an HTTP connection, so I tried with 254 and 255, but it didn't change anything.

I don't know if I use wrong the library or if it's a bug.
Of course i'm available for more precision.

Otherwise it's a great library, thanks to you.
Thanks in advance for the help.

@dtikhonov
Copy link
Contributor

If all the streams are the same priority, they should be sending in round-robin fashion: each "tick," the next stream is picked.

If that does not happen, it's likely a bug.

@mickael-cerisier
Copy link
Contributor Author

I agree with you, that why I think it's a bug.

@mickael-cerisier
Copy link
Contributor Author

6608 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] engine: decref conn 48E9E66CABAF7428, 'HTA' -> 'HA' (task=29772)
6609 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] engine: decref conn 48E9E66CABAF7428, 'HA' -> 'H' (task=29772)
6610 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] conn: Processing ACK (task=29772)
6611 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] sendctl: Got ACK frame, largest acked: 3499; delta: 24 (task=29772)
6612 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] sendctl: ACK comes after a period of quiescence (task=29772)
6613 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] bbr: was quiet (task=29772)
6614 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] sendctl: Smallest unacked: 3496 (task=29772)
6615 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] stream: ACKed; n_unacked: 3 (task=29772)
6616 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] sendctl: acking via regular record #3496 (task=29772)
6617 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] bw-sampler: send rate: 18446744073709551615; ack rate: 27514018 (task=29772)
6618 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] bw-sampler: packet 3496 acked, bandwidth: 27514018 bps (task=29772)
6619 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] stream: ACKed; n_unacked: 2 (task=29772)
6620 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] sendctl: acking via regular record #3497 (task=29772)
6621 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] bw-sampler: send rate: 18446744073709551615; ack rate: 55028037 (task=29772)
6622 2023-06-27T14:26:07.488 [4D] TRACE - [QUIC] bw-sampler: packet 3497 acked, bandwidth: 55028037 bps (task=29772)
6623 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] stream: ACKed; n_unacked: 1 (task=29772)
6624 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: acking via regular record #3498 (task=29772)
6625 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bw-sampler: send rate: 18446744073709551615; ack rate: 82542056 (task=29772)
6626 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bw-sampler: packet 3498 acked, bandwidth: 82542056 bps (task=29772)
6627 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] stream: ACKed; n_unacked: 0 (task=29772)
6628 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: acking via regular record #3499 (task=29772)
6629 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bw-sampler: send rate: 18446744073709551615; ack rate: 110056074 (task=29772)
6630 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bw-sampler: packet 3499 acked, bandwidth: 110056074 bps (task=29772)
6631 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: packno 3499; rtt: 428; delta: 24; new srtt: 394 (task=29772)
6632 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: clear sc_n_consec_rtos, sc_n_hsk, sc_ntlp (task=29772)
6633 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: No retransmittable packets: clear alarm (task=29772)
6634 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bbr: end_ack; mode: PROBE_BW; in_flight: 0 (task=29772)
6635 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bbr: up round count to 842; new rt end: 3499 (task=29772)
6636 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bbr: advanced gain cycle, pacing gain set to 1.00 (task=29772)
6637 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bbr: BW estimate: 112959232 (task=29772)
6638 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 0 (task=29772)
6639 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 4 (task=29772)
6640 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 12 (task=29772)
6641 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 16 (task=29772)
6642 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 20 (task=29772)
6643 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 24 (task=29772)
6644 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 28 (task=29772)
6645 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 32 (task=29772)
6646 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 36 (task=29772)
6647 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 40 (task=29772)
6648 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 44 (task=29772)
6649 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 48 (task=29772)
6650 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 52 (task=29772)
6651 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 56 (task=29772)
6652 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 60 (task=29772)
6653 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 64 (task=29772)
6654 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 68 (task=29772)
6655 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 72 (task=29772)
6656 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: add stream 76 (task=29772)
6657 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: initialized; # elems: 19; sets: [ 00000100, 00000000 ] (task=29772)
6658 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 0, incr: 0, priority 8 (task=29772)
6659 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 4, incr: 0, priority 8 (task=29772)
6660 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 12, incr: 0, priority 8 (task=29772)
6661 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 16, incr: 0, priority 8 (task=29772)
6662 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 20, incr: 0, priority 8 (task=29772)
6663 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 24, incr: 0, priority 8 (task=29772)
6664 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 28, incr: 0, priority 8 (task=29772)
6665 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 32, incr: 0, priority 8 (task=29772)
6666 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 36, incr: 0, priority 8 (task=29772)
6667 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 40, incr: 0, priority 8 (task=29772)
6668 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 44, incr: 0, priority 8 (task=29772)
6669 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 48, incr: 0, priority 8 (task=29772)
6670 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 52, incr: 0, priority 8 (task=29772)
6671 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 56, incr: 0, priority 8 (task=29772)
6672 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 60, incr: 0, priority 8 (task=29772)
6673 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 64, incr: 0, priority 8 (task=29772)
6674 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 68, incr: 0, priority 8 (task=29772)
6675 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 72, incr: 0, priority 8 (task=29772)
6676 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 76, incr: 0, priority 8 (task=29772)
6677 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 0 (unacked_all: 0); cwnd: 5840; ccfc: 3936747/4726971 (task=29772)
6678 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: APP pns ACK queued opportunistically (task=29772)
6679 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: created packet #3500 (task=29772)
6680 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: created packet #3500 SHORT; flags: version=0, nonce=0, conn_id=1 (task=29772)
6681 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: ACK bytes: 028000853F050000 (task=29772)
6682 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: generated ACK frame: [34111-34111] (task=29772)
6683 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: Put 8 bytes of ACK frame into packet 3500 on outgoing queue (task=29772)
6684 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: APP pns ACK state reset (task=29772)
6685 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 48 (task=29772)
6686 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 32 (task=29772)
6687 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 28 (task=29772)
6688 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 68 (task=29772)
6689 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 36 (task=29772)
6690 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 44 (task=29772)
6691 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 40 (task=29772)
6692 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 52 (task=29772)
6693 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 56 (task=29772)
6694 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 72 (task=29772)
6695 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 64 (task=29772)
6696 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 60 (task=29772)
6697 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 76 (task=29772)
6698 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: add stream 24 (task=29772)
6699 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: initialized; # elems: 14; sets: [ 00000100, 00000000 ] (task=29772)
6700 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: lsquic_hpi_next: return stream 24, incr: 0, priority 8 (task=29772)
6701 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] stream: dispatch_write_events (task=29772)
6702 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] stream: increase cc_sent by 1431 to 3938178 (task=29772)
6703 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: generated STREAM frame: stream 24, offset: 3929395, size: 1431, fin: 0 (task=29772)
6704 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 1472 (unacked_all: 0); cwnd: 5840; ccfc: 3938178/4726971 (task=29772)
6705 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: created packet #3501 (task=29772)
6706 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: created packet #3501 SHORT; flags: version=0, nonce=0, conn_id=1 (task=29772)
6707 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] stream: increase cc_sent by 1440 to 3939618 (task=29772)
6708 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: generated STREAM frame: stream 24, offset: 3930826, size: 1440, fin: 0 (task=29772)
6709 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 2944 (unacked_all: 0); cwnd: 5840; ccfc: 3939618/4726971 (task=29772)
6710 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: created packet #3502 (task=29772)
6711 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: created packet #3502 SHORT; flags: version=0, nonce=0, conn_id=1 (task=29772)
6712 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] stream: increase cc_sent by 1440 to 3941058 (task=29772)
6713 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: generated STREAM frame: stream 24, offset: 3932266, size: 1440, fin: 0 (task=29772)
6714 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 4416 (unacked_all: 0); cwnd: 5840; ccfc: 3941058/4726971 (task=29772)
6715 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: created packet #3503 (task=29772)
6716 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: created packet #3503 SHORT; flags: version=0, nonce=0, conn_id=1 (task=29772)
6717 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] stream: increase cc_sent by 1440 to 3942498 (task=29772)
6718 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: generated STREAM frame: stream 24, offset: 3933706, size: 1440, fin: 0 (task=29772)
6719 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 0); cwnd: 5840; ccfc: 3942498/4726971 (task=29772)
6720 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] LSQuicStream partial onwrite: 5751 (stream_id=48E9E66CABAF7428-24, peerAddr=192.168.56.1, peerPort=19813, task=29772)
6721 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] hpi: write-high: lsquic_hpi_next: return stream 28, incr: 0, priority 8 (task=29772)
6722 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 0); cwnd: 5840; ccfc: 3942498/4726971 (task=29772)
6723 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 0); cwnd: 5840; ccfc: 3942498/4726971 (task=29772)
6724 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: incref conn 48E9E66CABAF7428, 'H' -> 'HO' (task=29772)
6725 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: incref conn 48E9E66CABAF7428, 'HO' -> 'HOK' (task=29772)
6726 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: batched packet #3500 for connection 48E9E66CABAF7428 (task=29772)
6727 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: batched packet #3501 for connection 48E9E66CABAF7428 (task=29772)
6728 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: batched packet #3502 for connection 48E9E66CABAF7428 (task=29772)
6729 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: batched packet #3503 for connection 48E9E66CABAF7428 (task=29772)
6730 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: no more scheduled packets (task=29772)
6731 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: batched all outgoing packets for full conn 48E9E66CABAF7428 (task=29772)
6732 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] handshake: flush header protection application, count: 4 (task=29772)
6733 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] handshake: apply header protection using mask 669690FA03 (task=29772)
6734 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] handshake: apply header protection using mask 97F29D0C20 (task=29772)
6735 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] handshake: apply header protection using mask 3DF2A1F592 (task=29772)
6736 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] handshake: apply header protection using mask 4ECAD4F0CD (task=29772)
6737 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] LSQuicClient send_packets_one_by_one count=4 (task=29772)
6738 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: packets out returned 4 (out of 4) (task=29772)
6739 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: TX packet #3500 SHORT (STREAM ACK), size 1472, ecn: 0, spin: 1; kp: 0, path: 0, flags: 1082171960; Q: 0; L: 0 (task=29772)
6740 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: sent packet #3500 (STREAM ACK) (task=29772)
6741 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bw-sampler: add info for packet 3500 (task=29772)
6742 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: set RETX_APP pns alarm to 255625490446 (25591), mode RETX_MODE_TLP (task=29772)
6743 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: TX packet #3501 SHORT (STREAM), size 1472, ecn: 0, spin: 1; kp: 0, path: 0, flags: 1082171912; Q: 0; L: 0 (task=29772)
6744 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: sent packet #3501 (STREAM) (task=29772)
6745 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bw-sampler: add info for packet 3501 (task=29772)
6746 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: TX packet #3502 SHORT (STREAM), size 1472, ecn: 0, spin: 1; kp: 0, path: 0, flags: 1082171912; Q: 0; L: 0 (task=29772)
6747 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: sent packet #3502 (STREAM) (task=29772)
6748 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bw-sampler: add info for packet 3502 (task=29772)
6749 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: TX packet #3503 SHORT (STREAM), size 1472, ecn: 0, spin: 1; kp: 0, path: 0, flags: 1082171912; Q: 0; L: 0 (task=29772)
6750 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: sent packet #3503 (STREAM) (task=29772)
6751 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] bw-sampler: add info for packet 3503 (task=29772)
6752 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: decref conn 48E9E66CABAF7428, 'HOK' -> 'HK' (task=29772)
6753 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: send_packets_out: sent 4 packets (task=29772)
6754 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: decref conn 48E9E66CABAF7428, 'HK' -> 'H' (task=29772)
6755 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: tickable: stream 48 can be written to (task=29772)
6756 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 5888); cwnd: 5840; ccfc: 3942498/4726971 (task=29772)
6757 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: not tickable (task=29772)
6758 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: incref conn 48E9E66CABAF7428, 'H' -> 'HA' (task=29772)
6759 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] engine: incref conn 48E9E66CABAF7428, 'HA' -> 'HTA' (task=29772)
6760 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] handshake: strip header protection using mask DE7DDEC09B (task=29772)
6761 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] handshake: pre-decode packno: 34112 (task=29772)
6762 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: RX packet #34112 SHORT, size: 39; ecn: 0, spin: 1; path: 0; Q: 0; L: 0 (task=29772)
6763 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: about to process QUIC_FRAME_ACK frame (task=29772)
6764 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: RX ACK frame: [3503-3500] (task=29772)
6765 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: Saved ACK (task=29772)
6766 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: about to process QUIC_FRAME_MAX_DATA frame (task=29772)
6767 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] event: RX MAX_DATA frame; offset: 5515362 (task=29772)
6768 2023-06-27T14:26:07.489 [4D] TRACE - [QUIC] conn: max data goes from 4726971 to 5515362 (task=29772)
6769 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] conn: about to process QUIC_FRAME_PING frame (task=29772)
6770 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: RX PING frame (task=29772)
6771 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] conn: received PING frame, update last progress to 0 (task=29772)
6772 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] conn: APP pns ACK alarm set to 255625466277 (task=29772)
6773 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] qlog: [255625465277,"TRANSPORT","PACKET_RX","LINE",{"raw":"6748e9e66cabaf7428f89ece24a841954b8b40ae68f2c7d8dfc3f3a2118456","header":{"type":"SHORT","payload_length":"23","packet_number":"34112"},"frames":[{"frame_type":"ACK"},{"frame_type":"PING"},{"frame_type":"MAX_DATA"}]}] (task=29772)
6774 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] LSQuicEngine OnUvRead size:39 flags:0 (peerAddr=192.168.56.1, peerPort=19813, task=29772)
6775 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: decref conn 48E9E66CABAF7428, 'HTA' -> 'HA' (task=29772)
6776 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: decref conn 48E9E66CABAF7428, 'HA' -> 'H' (task=29772)
6777 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] conn: Processing ACK (task=29772)
6778 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: Got ACK frame, largest acked: 3503; delta: 24 (task=29772)
6779 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: ACK comes after a period of quiescence (task=29772)
6780 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bbr: was quiet (task=29772)
6781 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: Smallest unacked: 3500 (task=29772)
6782 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: ACKed; n_unacked: 3 (task=29772)
6783 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: acking via regular record #3500 (task=29772)
6784 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: send rate: 18446744073709551615; ack rate: 27905213 (task=29772)
6785 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: packet 3500 acked, bandwidth: 27905213 bps (task=29772)
6786 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: ACKed; n_unacked: 2 (task=29772)
6787 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: acking via regular record #3501 (task=29772)
6788 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: send rate: 18446744073709551615; ack rate: 55810426 (task=29772)
6789 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: packet 3501 acked, bandwidth: 55810426 bps (task=29772)
6790 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: ACKed; n_unacked: 1 (task=29772)
6791 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: acking via regular record #3502 (task=29772)
6792 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: send rate: 18446744073709551615; ack rate: 83715639 (task=29772)
6793 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: packet 3502 acked, bandwidth: 83715639 bps (task=29772)
6794 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: ACKed; n_unacked: 0 (task=29772)
6795 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: acking via regular record #3503 (task=29772)
6796 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: send rate: 18446744073709551615; ack rate: 111620853 (task=29772)
6797 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: packet 3503 acked, bandwidth: 111620853 bps (task=29772)
6798 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: packno 3503; rtt: 422; delta: 24; new srtt: 394 (task=29772)
6799 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: clear sc_n_consec_rtos, sc_n_hsk, sc_ntlp (task=29772)
6800 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: No retransmittable packets: clear alarm (task=29772)
6801 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bbr: end_ack; mode: PROBE_BW; in_flight: 0 (task=29772)
6802 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bbr: up round count to 843; new rt end: 3503 (task=29772)
6803 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bbr: advanced gain cycle, pacing gain set to 1.00 (task=29772)
6804 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bbr: BW estimate: 112959232 (task=29772)
6805 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 0 (task=29772)
6806 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 4 (task=29772)
6807 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 12 (task=29772)
6808 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 16 (task=29772)
6809 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 20 (task=29772)
6810 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 24 (task=29772)
6811 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 28 (task=29772)
6812 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 32 (task=29772)
6813 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 36 (task=29772)
6814 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 40 (task=29772)
6815 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 44 (task=29772)
6816 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 48 (task=29772)
6817 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 52 (task=29772)
6818 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 56 (task=29772)
6819 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 60 (task=29772)
6820 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 64 (task=29772)
6821 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 68 (task=29772)
6822 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 72 (task=29772)
6823 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: add stream 76 (task=29772)
6824 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: initialized; # elems: 19; sets: [ 00000100, 00000000 ] (task=29772)
6825 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 0, incr: 0, priority 8 (task=29772)
6826 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 4, incr: 0, priority 8 (task=29772)
6827 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 12, incr: 0, priority 8 (task=29772)
6828 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 16, incr: 0, priority 8 (task=29772)
6829 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 20, incr: 0, priority 8 (task=29772)
6830 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 24, incr: 0, priority 8 (task=29772)
6831 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 28, incr: 0, priority 8 (task=29772)
6832 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 32, incr: 0, priority 8 (task=29772)
6833 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 36, incr: 0, priority 8 (task=29772)
6834 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 40, incr: 0, priority 8 (task=29772)
6835 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 44, incr: 0, priority 8 (task=29772)
6836 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 48, incr: 0, priority 8 (task=29772)
6837 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 52, incr: 0, priority 8 (task=29772)
6838 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 56, incr: 0, priority 8 (task=29772)
6839 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 60, incr: 0, priority 8 (task=29772)
6840 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 64, incr: 0, priority 8 (task=29772)
6841 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 68, incr: 0, priority 8 (task=29772)
6842 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 72, incr: 0, priority 8 (task=29772)
6843 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: read-0: lsquic_hpi_next: return stream 76, incr: 0, priority 8 (task=29772)
6844 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 0 (unacked_all: 0); cwnd: 5840; ccfc: 3942498/5515362 (task=29772)
6845 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] conn: APP pns ACK queued opportunistically (task=29772)
6846 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: created packet #3504 (task=29772)
6847 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: created packet #3504 SHORT; flags: version=0, nonce=0, conn_id=1 (task=29772)
6848 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] conn: ACK bytes: 0280008540060000 (task=29772)
6849 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: generated ACK frame: [34112-34112] (task=29772)
6850 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] conn: Put 8 bytes of ACK frame into packet 3504 on outgoing queue (task=29772)
6851 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] conn: APP pns ACK state reset (task=29772)
6852 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 48 (task=29772)
6853 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 32 (task=29772)
6854 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 28 (task=29772)
6855 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 68 (task=29772)
6856 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 36 (task=29772)
6857 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 44 (task=29772)
6858 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 40 (task=29772)
6859 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 52 (task=29772)
6860 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 56 (task=29772)
6861 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 72 (task=29772)
6862 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 64 (task=29772)
6863 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 60 (task=29772)
6864 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 76 (task=29772)
6865 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: add stream 24 (task=29772)
6866 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: initialized; # elems: 14; sets: [ 00000100, 00000000 ] (task=29772)
6867 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: lsquic_hpi_next: return stream 24, incr: 0, priority 8 (task=29772)
6868 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: dispatch_write_events (task=29772)
6869 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: increase cc_sent by 1431 to 3943929 (task=29772)
6870 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: generated STREAM frame: stream 24, offset: 3935146, size: 1431, fin: 0 (task=29772)
6871 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 1472 (unacked_all: 0); cwnd: 5840; ccfc: 3943929/5515362 (task=29772)
6872 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: created packet #3505 (task=29772)
6873 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: created packet #3505 SHORT; flags: version=0, nonce=0, conn_id=1 (task=29772)
6874 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: increase cc_sent by 1440 to 3945369 (task=29772)
6875 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: generated STREAM frame: stream 24, offset: 3936577, size: 1440, fin: 0 (task=29772)
6876 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 2944 (unacked_all: 0); cwnd: 5840; ccfc: 3945369/5515362 (task=29772)
6877 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: created packet #3506 (task=29772)
6878 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: created packet #3506 SHORT; flags: version=0, nonce=0, conn_id=1 (task=29772)
6879 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: increase cc_sent by 1440 to 3946809 (task=29772)
6880 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: generated STREAM frame: stream 24, offset: 3938017, size: 1440, fin: 0 (task=29772)
6881 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 4416 (unacked_all: 0); cwnd: 5840; ccfc: 3946809/5515362 (task=29772)
6882 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: created packet #3507 (task=29772)
6883 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: created packet #3507 SHORT; flags: version=0, nonce=0, conn_id=1 (task=29772)
6884 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] stream: increase cc_sent by 1440 to 3948249 (task=29772)
6885 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: generated STREAM frame: stream 24, offset: 3939457, size: 1440, fin: 0 (task=29772)
6886 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 0); cwnd: 5840; ccfc: 3948249/5515362 (task=29772)
6887 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] LSQuicStream partial onwrite: 5751 (stream_id=48E9E66CABAF7428-24, peerAddr=192.168.56.1, peerPort=19813, task=29772)
6888 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] hpi: write-high: lsquic_hpi_next: return stream 28, incr: 0, priority 8 (task=29772)
6889 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 0); cwnd: 5840; ccfc: 3948249/5515362 (task=29772)
6890 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 0); cwnd: 5840; ccfc: 3948249/5515362 (task=29772)
6891 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: incref conn 48E9E66CABAF7428, 'H' -> 'HO' (task=29772)
6892 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: incref conn 48E9E66CABAF7428, 'HO' -> 'HOK' (task=29772)
6893 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: batched packet #3504 for connection 48E9E66CABAF7428 (task=29772)
6894 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: batched packet #3505 for connection 48E9E66CABAF7428 (task=29772)
6895 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: batched packet #3506 for connection 48E9E66CABAF7428 (task=29772)
6896 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: batched packet #3507 for connection 48E9E66CABAF7428 (task=29772)
6897 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: no more scheduled packets (task=29772)
6898 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: batched all outgoing packets for full conn 48E9E66CABAF7428 (task=29772)
6899 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] handshake: flush header protection application, count: 4 (task=29772)
6900 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] handshake: apply header protection using mask FA5262CBFF (task=29772)
6901 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] handshake: apply header protection using mask D585B9EA39 (task=29772)
6902 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] handshake: apply header protection using mask A7E20999DD (task=29772)
6903 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] handshake: apply header protection using mask 5F1F111347 (task=29772)
6904 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] LSQuicClient send_packets_one_by_one count=4 (task=29772)
6905 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] engine: packets out returned 4 (out of 4) (task=29772)
6906 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: TX packet #3504 SHORT (STREAM ACK), size 1472, ecn: 0, spin: 0; kp: 0, path: 0, flags: 8430136; Q: 0; L: 0 (task=29772)
6907 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: sent packet #3504 (STREAM ACK) (task=29772)
6908 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: add info for packet 3504 (task=29772)
6909 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: set RETX_APP pns alarm to 255625491188 (25591), mode RETX_MODE_TLP (task=29772)
6910 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: TX packet #3505 SHORT (STREAM), size 1472, ecn: 0, spin: 0; kp: 0, path: 0, flags: 8430088; Q: 0; L: 0 (task=29772)
6911 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: sent packet #3505 (STREAM) (task=29772)
6912 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: add info for packet 3505 (task=29772)
6913 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: TX packet #3506 SHORT (STREAM), size 1472, ecn: 0, spin: 0; kp: 0, path: 0, flags: 8430088; Q: 0; L: 0 (task=29772)
6914 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] sendctl: sent packet #3506 (STREAM) (task=29772)
6915 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] bw-sampler: add info for packet 3506 (task=29772)
6916 2023-06-27T14:26:07.490 [4D] TRACE - [QUIC] event: TX packet #3507 SHORT (STREAM), size 1472, ecn: 0, spin: 0; kp: 0, path: 0, flags: 8430088; Q: 0; L: 0 (task=29772)
6917 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] sendctl: sent packet #3507 (STREAM) (task=29772)
6918 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] bw-sampler: add info for packet 3507 (task=29772)
6919 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] engine: decref conn 48E9E66CABAF7428, 'HOK' -> 'HK' (task=29772)
6920 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] engine: send_packets_out: sent 4 packets (task=29772)
6921 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] engine: decref conn 48E9E66CABAF7428, 'HK' -> 'H' (task=29772)
6922 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] conn: tickable: stream 48 can be written to (task=29772)
6923 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] sendctl: send_ctl_can_send: n_out: 5888 (unacked_all: 5888); cwnd: 5840; ccfc: 3948249/5515362 (task=29772)
6924 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] conn: not tickable (task=29772)
6925 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] engine: incref conn 48E9E66CABAF7428, 'H' -> 'HA' (task=29772)
6926 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] engine: incref conn 48E9E66CABAF7428, 'HA' -> 'HTA' (task=29772)
6927 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] handshake: strip header protection using mask 5E8663F041 (task=29772)
6928 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] handshake: pre-decode packno: 34113 (task=29772)
6929 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] event: RX packet #34113 SHORT, size: 33; ecn: 0, spin: 0; path: 0; Q: 0; L: 0 (task=29772)
6930 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] conn: about to process QUIC_FRAME_ACK frame (task=29772)
6931 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] event: RX ACK frame: [3507-3504] (task=29772)
6932 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] conn: Saved ACK (task=29772)
6933 2023-06-27T14:26:07.491 [4D] TRACE - [QUIC] qlog: [255625466021,"TRANSPORT","PACKET_RX","LINE",{"raw":"4748e9e66cabaf74280322b68fe81d593325144d18a2f4932d78e48fe133d0","header":{"type":"SHORT","payload_length":"17","packet_number":"34113"},"frames":[{"frame_type":"ACK"}]}] (task=29772)

This is a typical log of my problem, there are many streams that need to write, but only stream 24 writes successfully.

@Koukan
Copy link

Koukan commented Aug 2, 2023

Nobody can help me ?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants