Re: Difference in buffer behaviour between 8.89 and 8.9?

[rapier <rapier@xxxxxxx>]

Thanks! This worked well.

I'm still trying to figure out exactly which buffer is causing the 
problem but I can describe the behaviour a little better. There is some 
buffer that is a function of CHAN_SES_WINDOW_DEFAULT. After digging 
through the code I'm pretty sure it's c->output.

After an initial burst of transfer this buffer starts to grow up to some 
maximum value. Each round of data it gets causes sshbuf_reserve to call 
sshbuf_alloc which then reallocs the buffer and fires off memcpys. Until 
the buffer reaches that maximum none/little of it ends up getting 
consumed. I believe, and this mostly a guess, that it not getting 
consumed clamps the advertised receive window. Once it reaches that 
maximum consumption starts and throughput picks up again.

When CHAN_SES_WINDOW_DEFAULT is small (64*CSPD) this delay isn't 
noticible outside of really looking for it in the sshbuf logs. When CSWD 
is large the delay becomes noticable, especially at higher RTTs when it 
needs to handle more outstanding data.

What I'm trying to figure out is how to tell sshbuf_reserve to 
selectively accelerate the growth of that buffer but I'm at a loss. The 
right place seems to be in channel_input_data but mucking about with 
sshbuf_put is failing. If you have any ideas please let me know.

Chris

On 5/24/22 7:27 PM, Damien Miller wrote:
> diff --git a/sshbuf-getput-basic.c b/sshbuf-getput-basic.c
> index 15a56cb..f845ac6 100644
> --- a/sshbuf-getput-basic.c
> +++ b/sshbuf-getput-basic.c
> @@ -194,7 +194,7 @@ sshbuf_get_string(struct sshbuf *buf, u_char **valp, size_t *lenp)
>   		return r;
>   	if (valp != NULL) {
>   		if ((*valp = malloc(len + 1)) == NULL) {
> -			SSHBUF_DBG(("SSH_ERR_ALLOC_FAIL"));
> +			SSHBUF_DBG("SSH_ERR_ALLOC_FAIL");
>   			return SSH_ERR_ALLOC_FAIL;
>   		}
>   		if (len != 0)
> @@ -225,7 +225,7 @@ sshbuf_get_string_direct(struct sshbuf *buf, const u_char **valp, size_t *lenp)
>   		*lenp = len;
>   	if (sshbuf_consume(buf, len + 4) != 0) {
>   		/* Shouldn't happen */
> -		SSHBUF_DBG(("SSH_ERR_INTERNAL_ERROR"));
> +		SSHBUF_DBG("SSH_ERR_INTERNAL_ERROR");
>   		SSHBUF_ABORT();
>   		return SSH_ERR_INTERNAL_ERROR;
>   	}
> @@ -244,16 +244,16 @@ sshbuf_peek_string_direct(const struct sshbuf *buf, const u_char **valp,
>   	if (lenp != NULL)
>   		*lenp = 0;
>   	if (sshbuf_len(buf) < 4) {
> -		SSHBUF_DBG(("SSH_ERR_MESSAGE_INCOMPLETE"));
> +		SSHBUF_DBG("SSH_ERR_MESSAGE_INCOMPLETE");
>   		return SSH_ERR_MESSAGE_INCOMPLETE;
>   	}
>   	len = PEEK_U32(p);
>   	if (len > SSHBUF_SIZE_MAX - 4) {
> -		SSHBUF_DBG(("SSH_ERR_STRING_TOO_LARGE"));
> +		SSHBUF_DBG("SSH_ERR_STRING_TOO_LARGE");
>   		return SSH_ERR_STRING_TOO_LARGE;
>   	}
>   	if (sshbuf_len(buf) - 4 < len) {
> -		SSHBUF_DBG(("SSH_ERR_MESSAGE_INCOMPLETE"));
> +		SSHBUF_DBG("SSH_ERR_MESSAGE_INCOMPLETE");
>   		return SSH_ERR_MESSAGE_INCOMPLETE;
>   	}
>   	if (valp != NULL)
> @@ -279,14 +279,14 @@ sshbuf_get_cstring(struct sshbuf *buf, char **valp, size_t *lenp)
>   	/* Allow a \0 only at the end of the string */
>   	if (len > 0 &&
>   	    (z = memchr(p , '\0', len)) != NULL && z < p + len - 1) {
> -		SSHBUF_DBG(("SSH_ERR_INVALID_FORMAT"));
> +		SSHBUF_DBG("SSH_ERR_INVALID_FORMAT");
>   		return SSH_ERR_INVALID_FORMAT;
>   	}
>   	if ((r = sshbuf_skip_string(buf)) != 0)
>   		return -1;
>   	if (valp != NULL) {
>   		if ((*valp = malloc(len + 1)) == NULL) {
> -			SSHBUF_DBG(("SSH_ERR_ALLOC_FAIL"));
> +			SSHBUF_DBG("SSH_ERR_ALLOC_FAIL");
>   			return SSH_ERR_ALLOC_FAIL;
>   		}
>   		if (len != 0)
> @@ -513,7 +513,7 @@ sshbuf_put_string(struct sshbuf *buf, const void *v, size_t len)
>   	int r;
>   
>   	if (len > SSHBUF_SIZE_MAX - 4) {
> -		SSHBUF_DBG(("SSH_ERR_NO_BUFFER_SPACE"));
> +		SSHBUF_DBG("SSH_ERR_NO_BUFFER_SPACE");
>   		return SSH_ERR_NO_BUFFER_SPACE;
>   	}
>   	if ((r = sshbuf_reserve(buf, len + 4, &d)) < 0)
> @@ -571,7 +571,7 @@ sshbuf_put_bignum2_bytes(struct sshbuf *buf, const void *v, size_t len)
>   	int r, prepend;
>   
>   	if (len > SSHBUF_SIZE_MAX - 5) {
> -		SSHBUF_DBG(("SSH_ERR_NO_BUFFER_SPACE"));
> +		SSHBUF_DBG("SSH_ERR_NO_BUFFER_SPACE");
>   		return SSH_ERR_NO_BUFFER_SPACE;
>   	}
>   	/* Skip leading zero bytes */
> @@ -621,7 +621,7 @@ sshbuf_get_bignum2_bytes_direct(struct sshbuf *buf,
>   		*lenp = len;
>   	if (sshbuf_consume(buf, olen + 4) != 0) {
>   		/* Shouldn't happen */
> -		SSHBUF_DBG(("SSH_ERR_INTERNAL_ERROR"));
> +		SSHBUF_DBG("SSH_ERR_INTERNAL_ERROR");
>   		SSHBUF_ABORT();
>   		return SSH_ERR_INTERNAL_ERROR;
>   	}
> diff --git a/sshbuf-getput-crypto.c b/sshbuf-getput-crypto.c
> index e3e71ba..b22c1f3 100644
> --- a/sshbuf-getput-crypto.c
> +++ b/sshbuf-getput-crypto.c
> @@ -78,7 +78,7 @@ sshbuf_get_ec(struct sshbuf *buf, EC_POINT *v, const EC_GROUP *g)
>   	/* Skip string */
>   	if (sshbuf_get_string_direct(buf, NULL, NULL) != 0) {
>   		/* Shouldn't happen */
> -		SSHBUF_DBG(("SSH_ERR_INTERNAL_ERROR"));
> +		SSHBUF_DBG("SSH_ERR_INTERNAL_ERROR");
>   		SSHBUF_ABORT();
>   		return SSH_ERR_INTERNAL_ERROR;
>   	}
> @@ -94,7 +94,7 @@ sshbuf_get_eckey(struct sshbuf *buf, EC_KEY *v)
>   	size_t len;
>   
>   	if (pt == NULL) {
> -		SSHBUF_DBG(("SSH_ERR_ALLOC_FAIL"));
> +		SSHBUF_DBG("SSH_ERR_ALLOC_FAIL");
>   		return SSH_ERR_ALLOC_FAIL;
>   	}
>   	if ((r = sshbuf_peek_string_direct(buf, &d, &len)) < 0) {
> @@ -113,7 +113,7 @@ sshbuf_get_eckey(struct sshbuf *buf, EC_KEY *v)
>   	/* Skip string */
>   	if (sshbuf_get_string_direct(buf, NULL, NULL) != 0) {
>   		/* Shouldn't happen */
> -		SSHBUF_DBG(("SSH_ERR_INTERNAL_ERROR"));
> +		SSHBUF_DBG("SSH_ERR_INTERNAL_ERROR");
>   		SSHBUF_ABORT();
>   		return SSH_ERR_INTERNAL_ERROR;
>   	}
> diff --git a/sshbuf.c b/sshbuf.c
> index 8db22a0..685dbb8 100644
> --- a/sshbuf.c
> +++ b/sshbuf.c
> @@ -39,7 +39,7 @@ sshbuf_check_sanity(const struct sshbuf *buf)
>   	    buf->size > buf->alloc ||
>   	    buf->off > buf->size)) {
>   		/* Do not try to recover from corrupted buffer internals */
> -		SSHBUF_DBG(("SSH_ERR_INTERNAL_ERROR"));
> +		SSHBUF_DBG("SSH_ERR_INTERNAL_ERROR");
>   		ssh_signal(SIGSEGV, SIG_DFL);
>   		raise(SIGSEGV);
>   		return SSH_ERR_INTERNAL_ERROR;
> @@ -50,7 +50,7 @@ sshbuf_check_sanity(const struct sshbuf *buf)
>   static void
>   sshbuf_maybe_pack(struct sshbuf *buf, int force)
>   {
> -	SSHBUF_DBG(("force %d", force));
> +	SSHBUF_DBG("force %d", force);
>   	SSHBUF_TELL("pre-pack");
>   	if (buf->off == 0 || buf->readonly || buf->refcount > 1)
>   		return;
> @@ -221,7 +221,7 @@ sshbuf_set_max_size(struct sshbuf *buf, size_t max_size)
>   	u_char *dp;
>   	int r;
>   
> -	SSHBUF_DBG(("set max buf = %p len = %zu", buf, max_size));
> +	SSHBUF_DBG("set max buf = %p len = %zu", buf, max_size);
>   	if ((r = sshbuf_check_sanity(buf)) != 0)
>   		return r;
>   	if (max_size == buf->max_size)
> @@ -239,7 +239,7 @@ sshbuf_set_max_size(struct sshbuf *buf, size_t max_size)
>   			rlen = ROUNDUP(buf->size, SSHBUF_SIZE_INC);
>   		if (rlen > max_size)
>   			rlen = max_size;
> -		SSHBUF_DBG(("new alloc = %zu", rlen));
> +		SSHBUF_DBG("new alloc = %zu", rlen);
>   		if ((dp = recallocarray(buf->d, buf->alloc, rlen, 1)) == NULL)
>   			return SSH_ERR_ALLOC_FAIL;
>   		buf->cd = buf->d = dp;
> @@ -307,7 +307,7 @@ sshbuf_allocate(struct sshbuf *buf, size_t len)
>   	u_char *dp;
>   	int r;
>   
> -	SSHBUF_DBG(("allocate buf = %p len = %zu", buf, len));
> +	SSHBUF_DBG("allocate buf = %p len = %zu", buf, len);
>   	if ((r = sshbuf_check_reserve(buf, len)) != 0)
>   		return r;
>   	/*
> @@ -325,12 +325,12 @@ sshbuf_allocate(struct sshbuf *buf, size_t len)
>   	 */
>   	need = len + buf->size - buf->alloc;
>   	rlen = ROUNDUP(buf->alloc + need, SSHBUF_SIZE_INC);
> -	SSHBUF_DBG(("need %zu initial rlen %zu", need, rlen));
> +	SSHBUF_DBG("need %zu initial rlen %zu", need, rlen);
>   	if (rlen > buf->max_size)
>   		rlen = buf->alloc + need;
> -	SSHBUF_DBG(("adjusted rlen %zu", rlen));
> +	SSHBUF_DBG("adjusted rlen %zu", rlen);
>   	if ((dp = recallocarray(buf->d, buf->alloc, rlen, 1)) == NULL) {
> -		SSHBUF_DBG(("realloc fail"));
> +		SSHBUF_DBG("realloc fail");
>   		return SSH_ERR_ALLOC_FAIL;
>   	}
>   	buf->alloc = rlen;
> @@ -352,7 +352,7 @@ sshbuf_reserve(struct sshbuf *buf, size_t len, u_char **dpp)
>   	if (dpp != NULL)
>   		*dpp = NULL;
>   
> -	SSHBUF_DBG(("reserve buf = %p len = %zu", buf, len));
> +	SSHBUF_DBG("reserve buf = %p len = %zu", buf, len);
>   	if ((r = sshbuf_allocate(buf, len)) != 0)
>   		return r;
>   
> @@ -368,7 +368,7 @@ sshbuf_consume(struct sshbuf *buf, size_t len)
>   {
>   	int r;
>   
> -	SSHBUF_DBG(("len = %zu", len));
> +	SSHBUF_DBG("len = %zu", len);
>   	if ((r = sshbuf_check_sanity(buf)) != 0)
>   		return r;
>   	if (len == 0)
> @@ -388,7 +388,7 @@ sshbuf_consume_end(struct sshbuf *buf, size_t len)
>   {
>   	int r;
>   
> -	SSHBUF_DBG(("len = %zu", len));
> +	SSHBUF_DBG("len = %zu", len);
>   	if ((r = sshbuf_check_sanity(buf)) != 0)
>   		return r;
>   	if (len == 0)
> diff --git a/sshbuf.h b/sshbuf.h
> index 9624c43..cc3c34a 100644
> --- a/sshbuf.h
> +++ b/sshbuf.h
> @@ -396,16 +396,17 @@ u_int	sshbuf_refcount(const struct sshbuf *buf);
>   
>   # ifdef SSHBUF_DEBUG
>   #  define SSHBUF_TELL(what) do { \
> -		printf("%s:%d %s: %s size %zu alloc %zu off %zu max %zu\n", \
> +		fprintf(stderr, \
> +		    "%s:%d %s: %s size %zu alloc %zu off %zu max %zu\n", \
>   		    __FILE__, __LINE__, __func__, what, \
>   		    buf->size, buf->alloc, buf->off, buf->max_size); \
> -		fflush(stdout); \
> +		fflush(stderr); \
>   	} while (0)
> -#  define SSHBUF_DBG(x) do { \
> -		printf("%s:%d %s: ", __FILE__, __LINE__, __func__); \
> -		printf x; \
> -		printf("\n"); \
> -		fflush(stdout); \
> +#  define SSHBUF_DBG(...) do { \
> +		fprintf(stderr, "%s:%d %s: ", __FILE__, __LINE__, __func__); \
> +		fprintf(stderr, __VA_ARGS__); \
> +		fprintf(stderr, "\n"); \
> +		fflush(stderr); \
>   	} while (0)
>   # else
>   #  define SSHBUF_TELL(what)
_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@xxxxxxxxxxx
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev