Why does printing cause the heap break to increase by this much?

I wrote the following program,

#include <stdlib.h>
#include <stdio.h>
#include <unistd.h>
#include <time.h>
#include "rand.h"

int main (int argc, char* argv[]) {

  void *x = sbrk(0);
  printf("The initial top of the heap is %p.\n", x);
  void *y = sbrk(0);
  printf("The current top of the heap is %p.\n", y);
  printf("The difference is %d (%x)\n", (int) (y-x), (int) (y-x));
  return 0;
}

I get why the heap break is different because it has to allocate heap space for the calls to print.

What I don't get is why, on my x86_64 Linux computer, the difference is specifically 25600 bytes.

Like, the string itself probably only needs a small number of bytes (each byte a char, add a little header data to the string in the heap), nowhere near needing even 1000 bytes right?

I had a bit of a guess that it might have something to do with paging -- which I don't really understand right yet. But from a brief search, it seems like paging only allocates about 4000 bytes at a time anyway, so that's probably not it either, right?

Maybe the various includes have something to do with it? I honestly don't know how that affects heap memory at all.

Anyway, the direct question is: Why does this program cause the heap memory to move by 25600 bytes?

Solution

Why does printing cause the heap break to increase by this much?

Because "printing" allocates memory, so moves the heap break. Running your program under debugger, you might observe:

(gdb) bt
#0  __GI___sbrk (increment=increment@entry=135168) at sbrk.c:37
#1  0x00007ffff7e45b36 in __glibc_morecore (increment=increment@entry=135168) at /usr/src/debug/glibc/glibc/malloc/morecore.c:29
#2  0x00007ffff7e46bfd in sysmalloc (nb=nb@entry=656, av=av@entry=0x7ffff7f87ac0 <main_arena>) at malloc.c:2709
#3  0x00007ffff7e47c5a in _int_malloc (av=av@entry=0x7ffff7f87ac0 <main_arena>, bytes=bytes@entry=640) at malloc.c:4481
#4  0x00007ffff7e47f37 in tcache_init () at malloc.c:3252
#5  0x00007ffff7e48776 in tcache_init () at malloc.c:3248
#6  __GI___libc_malloc (bytes=bytes@entry=1024) at malloc.c:3313
#7  0x00007ffff7e21f14 in __GI__IO_file_doallocate (fp=0x7ffff7f885c0 <_IO_2_1_stdout_>) at filedoalloc.c:101
#8  0x00007ffff7e31214 in __GI__IO_doallocbuf (fp=0x7ffff7f885c0 <_IO_2_1_stdout_>) at /usr/src/debug/glibc/glibc/libio/libioP.h:1030
#9  __GI__IO_doallocbuf (fp=fp@entry=0x7ffff7f885c0 <_IO_2_1_stdout_>) at genops.c:342
#10 0x00007ffff7e2f2e8 in _IO_new_file_overflow (f=0x7ffff7f885c0 <_IO_2_1_stdout_>, ch=-1) at fileops.c:745
#11 0x00007ffff7e2fde8 in _IO_new_file_xsputn (f=0x7ffff7f885c0 <_IO_2_1_stdout_>, data=<optimized out>, n=47)
    at /usr/src/debug/glibc/glibc/libio/libioP.h:1030
#12 _IO_new_file_xsputn (f=0x7ffff7f885c0 <_IO_2_1_stdout_>, data=<optimized out>, n=47) at fileops.c:1197
#13 0x00007ffff7dfd549 in __printf_buffer_flush_to_file (buf=buf@entry=0x7fffffffd9b0) at ../libio/libioP.h:1030
#14 0x00007ffff7dfd60c in __printf_buffer_to_file_done (buf=buf@entry=0x7fffffffd9b0) at printf_buffer_to_file.c:120
#15 0x00007ffff7e08e0c in __vfprintf_internal (s=0x7ffff7f885c0 <_IO_2_1_stdout_>, 
    format=0x555555556008 "The initial top of the heap is %p.\n", ap=ap@entry=0x7fffffffdab0, mode_flags=mode_flags@entry=0)
    at vfprintf-internal.c:1545
#16 0x00007ffff7dfccf3 in __printf (format=<optimized out>) at printf.c:33
#17 0x0000555555555181 in main ()

The allocation comes from glibc allocating buffer for stdout in https://github.com/lattera/glibc/blob/master/libio/fileops.c#L752 .