straceMalloc

stracing malloc
git clone https://noulin.net/git/straceMalloc.git
Log | Files | Refs | README

commit 77cb3738174ea8789494ccf65250db994e50be8c
parent f80cf63ee3b542d133d0860b7ccf790719441d18
Author: Remy Noulin <loader2x@gmail.com>
Date:   Thu,  4 Jan 2018 22:04:57 +0100

add malloc.c

.gitignore |   3 ++
README.md  | 130 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
malloc.c   |  31 +++++++++++++++
3 files changed, 164 insertions(+)

Diffstat:
M.gitignore | 3+++
AREADME.md | 130+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
Amalloc.c | 31+++++++++++++++++++++++++++++++
3 files changed, 164 insertions(+), 0 deletions(-)

diff --git a/.gitignore b/.gitignore @@ -1,3 +1,6 @@ +malloc +*.swp + # Prerequisites *.d diff --git a/README.md b/README.md @@ -0,0 +1,130 @@ +malloc.c is a program allocating blocks of memory with malloc. + +strace logs the system calls to the linux kernel, __mmap__ is the syscall used by malloc to allocate large blocks of RAM. + +The time spend in each malloc is measured, as you can see in the log, there is only a small variation. + +malloc.c allocates buffers increasingly big starting with 1KB and ending with 32MB. + +On my system, glibc allocates 128KB initially, so the first 6 allocations dont trigger a syscall. + +For buffers larger than 128KB, malloc calls the mmap syscall and the time spent in malloc is on average the same. + +When allocating buffers with alloca, the time spent in alloca depends on the buffer size, it takes more time for larger buffers. alloca never triggers a syscall as seen in the strace log. + +Compiling and running: + +``` +sheepy -c malloc.c +./malloc +strace ./malloc +``` + +malloc output: +``` +alloc +0 0x55949cb3a420 size: 1KB, time: 560ns +1 0x55949cb3a830 size: 2KB, time: 1612ns +2 0x55949cb3b040 size: 4KB, time: 1568ns +3 0x55949cb3c050 size: 8KB, time: 1303ns +4 0x55949cb3e060 size: 16KB, time: 1211ns +5 0x55949cb42070 size: 32KB, time: 1206ns +6 0x55949cb4a080 size: 64KB, time: 1217ns +7 0x7f6f87048010 size: 128KB, time: 2899ns +8 0x7f6f87007010 size: 256KB, time: 2574ns +9 0x7f6f86f86010 size: 512KB, time: 1868ns +10 0x7f6f867a8010 size: 1024KB, time: 2894ns +11 0x7f6f865a7010 size: 2048KB, time: 2189ns +12 0x7f6f861a6010 size: 4096KB, time: 2329ns +13 0x7f6f859a5010 size: 8192KB, time: 2323ns +14 0x7f6f849a4010 size: 16384KB, time: 1973ns +15 0x7f6f829a3010 size: 32768KB, time: 2191ns +s +alloca 0 0x7fff5b02ce70 size: 1KB, time: 39ns +alloca 1 0x7fff5b02c660 size: 2KB, time: 32ns +alloca 2 0x7fff5b02b650 size: 4KB, time: 31ns +alloca 3 0x7fff5b029640 size: 8KB, time: 1078ns +alloca 4 0x7fff5b025630 size: 16KB, time: 970ns +alloca 5 0x7fff5b01d620 size: 32KB, time: 1162ns +alloca 6 0x7fff5b00d610 size: 64KB, time: 978ns +alloca 7 0x7fff5afed600 size: 128KB, time: 1425ns +alloca 8 0x7fff5afad5f0 size: 256KB, time: 1044ns +alloca 9 0x7fff5af2d5e0 size: 512KB, time: 1148ns +alloca 10 0x7fff5ae2d5d0 size: 1024KB, time: 961ns +alloca 11 0x7fff5ac2d5c0 size: 2048KB, time: 1241ns +``` + +strace log on debian stretch: + +``` +write(1, "alloc\n", 6alloc +) = 6 +write(1, "0 0x55e346706420 size: 1024, tim"..., 410 0x55e346706420 size: 1024, time: 837ns +) = 41 +write(1, "1 0x55e346706830 size: 2048, tim"..., 421 0x55e346706830 size: 2048, time: 1960ns +) = 42 +write(1, "2 0x55e346707040 size: 4096, tim"..., 422 0x55e346707040 size: 4096, time: 1712ns +) = 42 +write(1, "3 0x55e346708050 size: 8192, tim"..., 423 0x55e346708050 size: 8192, time: 1588ns +) = 42 +write(1, "4 0x55e34670a060 size: 16384, ti"..., 434 0x55e34670a060 size: 16384, time: 1573ns +) = 43 +write(1, "5 0x55e34670e070 size: 32768, ti"..., 435 0x55e34670e070 size: 32768, time: 1486ns +) = 43 +write(1, "6 0x55e346716080 size: 65536, ti"..., 436 0x55e346716080 size: 65536, time: 1487ns +) = 43 +mmap(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f475dc2f000 +write(1, "7 0x7f475dc2f010 size: 131072, t"..., 457 0x7f475dc2f010 size: 131072, time: 20558ns +) = 45 +mmap(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f475dbee000 +write(1, "8 0x7f475dbee010 size: 262144, t"..., 458 0x7f475dbee010 size: 262144, time: 19708ns +) = 45 +mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f475db6d000 +write(1, "9 0x7f475db6d010 size: 524288, t"..., 459 0x7f475db6d010 size: 524288, time: 16711ns +) = 45 +mmap(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f475d38f000 +write(1, "10 0x7f475d38f010 size: 1048576,"..., 4710 0x7f475d38f010 size: 1048576, time: 19502ns +) = 47 +mmap(NULL, 2101248, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f475d18e000 +write(1, "11 0x7f475d18e010 size: 2097152,"..., 4711 0x7f475d18e010 size: 2097152, time: 18659ns +) = 47 +mmap(NULL, 4198400, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f475cd8d000 +write(1, "12 0x7f475cd8d010 size: 4194304,"..., 4712 0x7f475cd8d010 size: 4194304, time: 17346ns +) = 47 +mmap(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f475c58c000 +write(1, "13 0x7f475c58c010 size: 8388608,"..., 4713 0x7f475c58c010 size: 8388608, time: 18613ns +) = 47 +mmap(NULL, 16781312, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f475b58b000 +write(1, "14 0x7f475b58b010 size: 16777216"..., 4814 0x7f475b58b010 size: 16777216, time: 17792ns +) = 48 +mmap(NULL, 33558528, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f475958a000 +write(1, "15 0x7f475958a010 size: 33554432"..., 4815 0x7f475958a010 size: 33554432, time: 16998ns +) = 48 +write(1, "s\n", 2s +) = 2 +write(1, "alloca 0 0x7ffd31053480 size: 1K"..., 46alloca 0 0x7ffd31053480 size: 1KB, time: 51ns +) = 46 +write(1, "alloca 1 0x7ffd31052c70 size: 2K"..., 46alloca 1 0x7ffd31052c70 size: 2KB, time: 37ns +) = 46 +write(1, "alloca 2 0x7ffd31051c60 size: 4K"..., 46alloca 2 0x7ffd31051c60 size: 4KB, time: 60ns +) = 46 +write(1, "alloca 3 0x7ffd3104fc50 size: 8K"..., 48alloca 3 0x7ffd3104fc50 size: 8KB, time: 1897ns +) = 48 +write(1, "alloca 4 0x7ffd3104bc40 size: 16"..., 49alloca 4 0x7ffd3104bc40 size: 16KB, time: 1224ns +) = 49 +write(1, "alloca 5 0x7ffd31043c30 size: 32"..., 49alloca 5 0x7ffd31043c30 size: 32KB, time: 1266ns +) = 49 +write(1, "alloca 6 0x7ffd31033c20 size: 64"..., 49alloca 6 0x7ffd31033c20 size: 64KB, time: 1318ns +) = 49 +write(1, "alloca 7 0x7ffd31013c10 size: 12"..., 50alloca 7 0x7ffd31013c10 size: 128KB, time: 1908ns +) = 50 +write(1, "alloca 8 0x7ffd30fd3c00 size: 25"..., 50alloca 8 0x7ffd30fd3c00 size: 256KB, time: 2673ns +) = 50 +write(1, "alloca 9 0x7ffd30f53bf0 size: 51"..., 50alloca 9 0x7ffd30f53bf0 size: 512KB, time: 2582ns +) = 50 +write(1, "alloca 10 0x7ffd30e53be0 size: 1"..., 52alloca 10 0x7ffd30e53be0 size: 1024KB, time: 1391ns +) = 52 +write(1, "alloca 11 0x7ffd30c53bd0 size: 2"..., 52alloca 11 0x7ffd30c53bd0 size: 2048KB, time: 2118ns +) = 52 +exit_group(0) = ? +``` diff --git a/malloc.c b/malloc.c @@ -0,0 +1,31 @@ +#! /usr/bin/env sheepy + +#include "libsheepyObject.h" + +int argc; char **argv; + +int main(int ARGC, char** ARGV) { + + argc = ARGC; argv = ARGV; + + puts("alloc"); + char *s; + u64 start, end; + range(i, 16) { + start = getMonotonicTime(); + s = malloc((1<<i)*1024); + end = getMonotonicTime(); + printf("%d %p size: %ldKB, time: %ldns\n", (int)i ,s, 1<<i, end-start); + } + + s[0] = 's'; + s[1] = 0; + puts(s); + + range(i, 12) { + start = getMonotonicTime(); + s = alloca((1<<i)*1024); + end = getMonotonicTime(); + printf("alloca %d %p size: %ldKB, time: %ldns\n", (int)i ,s, 1<<i, end-start); + } +}