Valgrind yksinkertainen esimerkki.

Valgrind Esimerkki.





Eli tässä nyt edellisessä blogitekstissä lupaamani esimerkki valgrindin käytöstä. Demotakseni valgrindin toimintaa, kirjoitin seuraavanlaisen yksinkertaisen koodinpätkän, joka äkkinäisestä lukijasta saattaa näyttä ihan hyvältä. Siihen on kuitenkin "piilotettu" pari hyvin arkista bugia, jotka valgrind saattaa meille paljastaa...

yliluku.c:


#include <string.h>
#include <stdio.h>
#include <stdlib.h>
#define TAULUN_KOKO 4


int main()
{
size_t taulun_koko=0xFFFFFFFF;
const char merkkijono[]="foo bar foo bar lorum ipsum foo bar";
char taulukko[TAULUN_KOKO];
char *taulu2;
taulu2=malloc(TAULUN_KOKO);
memset(taulukko,0,TAULUN_KOKO);
memcpy(taulukko,merkkijono,TAULUN_KOKO);
taulun_koko=strlen(taulukko);
memcpy(taulu2,taulukko,taulun_koko);
printf("taulukon sisältö \"%s\"\n",taulukko);
printf("taulu2:n sisältö \"%s\"\n",taulu2);
printf("Taulun Koko Define = %u\n",TAULUN_KOKO);
printf("Taulun Koko strlen = %u\n",taulun_koko);
printf("Taulu2:n koko strlen = %u\n",strlen(taulu2));
return TAULUN_KOKO-taulun_koko;
}


Kas tässä. Huomaatko heti bugit? Et välttämättä, vaikka kyse on näin lyhyestä ja yksinkertaisesta pätkästä. Nyt jos tähän lisätään 10000 kertainen määrä koodia, lukuisia threadeja joilla on pääsy yhteisiin resursseihin, ja paljon monimutkaisempia rakenteita... Ja satunainen crashi... Mahdollisesti sellainen joka tapahtuu vasta tuntien toiminnan jälkeen, tai vain kerran 10 000 ajolla... Voit kuvitella miten työlästä sellaisen selvittäminen on. (Ja jos ongelma tulee esiin kerran 10 000 ajolla, ja mikäli teet laadukasta softaa sillä mahdollisesti tulee jossain vaiheessa olemaan 10 000 käyttäjää.. Sitä paitsi, ohjelmistoteollisuudessa Mr. Murphy osaa aina näytellä osansa. Yleensä ikävimmät viat tuuppaavat tulemaan esiin silloin, kun ne eivät saisi. Esim. juuri kun demoat ohjelmaasi firman tärkeimmälle asiakkaalle..)


No joo. Katsotaan siis mitä valgrind tuumaa. Annetaan komento:

valgrind --log-file=ylilukulogi --leak-check=full -v ./yliluku

Ohjelman tulostus:

[Matti@home ~]$ valgrind --log-file=ylilukulogi2 --leak-check=full -v ./yliluku
taulukon sisältö "foo foo bar foo bar lorum ipsum foo bar"
taulu2:n sisältö "foo foo bar foo bar lorum ipsum foo bar"
Taulun Koko Define = 4
Taulun Koko strlen = 39
Taulu2:n koko strlen = 40


Hmm.. "yllättäen" taulun koot eivät olekkaan yhtäsuuret, ja ne vieläpä vaihtelevat ajokertojen välillä. Myös viimeinen merkki (tai viimeiset merkit) tulostuksessa ovat hieman erikoisia... (Erikoinen merkki ei välttämättä näy selaimessa...)

Tutkitaanpa sitte valgrindin kirjoittama logitiedosto:

==5488== Memcheck, a memory error detector.
==5488== Copyright (C) 2002-2008, and GNU GPL'd, by Julian Seward et al.
==5488== Using LibVEX rev 1884, a library for dynamic binary translation.
==5488== Copyright (C) 2004-2008, and GNU GPL'd, by OpenWorks LLP.
==5488== Using valgrind-3.4.1, a dynamic binary instrumentation framework.
==5488== Copyright (C) 2000-2008, and GNU GPL'd, by Julian Seward et al.
==5488==
==5488== My PID = 5488, parent PID = 10064. Prog and args are:
==5488== ./yliluku
==5488==
--5488--
--5488-- Command line
--5488-- ./yliluku
--5488-- Startup, with flags:
--5488-- --log-file=ylilukulogi2
--5488-- --leak-check=full
--5488-- -v
--5488-- Contents of /proc/version:
--5488-- Linux version 2.6.27.5-117.fc10.i686 (mockbuild@x86-7.fedora.phx.redhat.com) (gcc version 4.3.2 20081105 (Red Hat 4.3.2-7) (GCC) ) #1 SMP Tue Nov 18 12:19:59 EST 2008
--5488-- Arch and hwcaps: X86, x86-sse1
--5488-- Page sizes: currently 4096, max supported 4096
--5488-- Valgrind library directory: /home/Matti/valgrind_new//lib/valgrind
--5488-- Reading syms from /lib/ld-2.9.so (0x4a7000)
--5488-- Reading debug info from /usr/lib/debug/lib/ld-2.9.so.debug ..
--5488-- Reading syms from /home/Matti/yliluku (0x8048000)
--5488-- Reading syms from /home/Matti/valgrind_new/lib/valgrind/x86-linux/memcheck (0x38000000)
--5488-- object doesn't have a dynamic symbol table
--5488-- Reading suppressions file: /home/Matti/valgrind_new//lib/valgrind/default.supp
--5488-- REDIR: 0x4c0440 (index) redirected to 0x3803cbc3 (vgPlain_x86_linux_REDIR_FOR_index)
--5488-- Reading syms from /home/Matti/valgrind_new/lib/valgrind/x86-linux/vgpreload_core.so (0x4000000)
--5488-- Reading syms from /home/Matti/valgrind_new/lib/valgrind/x86-linux/vgpreload_memcheck.so (0x4003000)
==5488== WARNING: new redirection conflicts with existing -- ignoring it
--5488-- new: 0x004c0440 (index ) R-> 0x040071b0 index
--5488-- REDIR: 0x4c0610 (strlen) redirected to 0x4007460 (strlen)
--5488-- Reading syms from /lib/libc-2.9.so (0x4cc000)
--5488-- Reading debug info from /usr/lib/debug/lib/libc-2.9.so.debug ..
--5488-- REDIR: 0x5437f0 (rindex) redirected to 0x4007090 (rindex)
--5488-- REDIR: 0x53f6c0 (malloc) redirected to 0x4006c80 (malloc)
--5488-- REDIR: 0x5450d0 (memset) redirected to 0x4008350 (memset)
--5488-- REDIR: 0x5455e0 (memcpy) redirected to 0x40078b0 (memcpy)
--5488-- REDIR: 0x543370 (strlen) redirected to 0x4007440 (strlen)
==5488== Invalid write of size 1
==5488== at 0x4007A07: memcpy (mc_replace_strmem.c:402)
==5488== by 0x8048545: main (yliluku.c:18)
==5488== Address 0x402d02c is 0 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
==5488==
==5488== Invalid write of size 1
==5488== at 0x4007A0F: memcpy (mc_replace_strmem.c:402)
==5488== by 0x8048545: main (yliluku.c:18)
==5488== Address 0x402d02d is 1 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
==5488==
==5488== Invalid write of size 1
==5488== at 0x4007A18: memcpy (mc_replace_strmem.c:402)
==5488== by 0x8048545: main (yliluku.c:18)
==5488== Address 0x402d02e is 2 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
==5488==
==5488== Invalid write of size 1
==5488== at 0x4007A21: memcpy (mc_replace_strmem.c:402)
==5488== by 0x8048545: main (yliluku.c:18)
==5488== Address 0x402d02f is 3 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
==5488==
==5488== Invalid write of size 1
==5488== at 0x4007A57: memcpy (mc_replace_strmem.c:402)
==5488== by 0x8048545: main (yliluku.c:18)
==5488== Address 0x402d04c is not stack'd, malloc'd or (recently) free'd
--5488-- REDIR: 0x548120 (strchrnul) redirected to 0x4008420 (strchrnul)
--5488-- REDIR: 0x545130 (mempcpy) redirected to 0x4008480 (mempcpy)
==5488==
==5488== Invalid read of size 1
==5488== at 0x4007453: strlen (mc_replace_strmem.c:242)
==5488== by 0x50F4CF: vfprintf (in /lib/libc-2.9.so)
==5488== by 0x51591F: printf (in /lib/libc-2.9.so)
==5488== by 0x804856B: main (yliluku.c:20)
==5488== Address 0x402d02c is 0 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
==5488==
==5488== Invalid read of size 1
==5488== at 0x5367DC: _IO_file_xsputn@@GLIBC_2.1 (in /lib/libc-2.9.so)
==5488== by 0x50ED5C: vfprintf (in /lib/libc-2.9.so)
==5488== by 0x51591F: printf (in /lib/libc-2.9.so)
==5488== by 0x804856B: main (yliluku.c:20)
==5488== Address 0x402d04f is not stack'd, malloc'd or (recently) free'd
==5488==
==5488== Invalid read of size 1
==5488== at 0x5367F4: _IO_file_xsputn@@GLIBC_2.1 (in /lib/libc-2.9.so)
==5488== by 0x50ED5C: vfprintf (in /lib/libc-2.9.so)
==5488== by 0x51591F: printf (in /lib/libc-2.9.so)
==5488== by 0x804856B: main (yliluku.c:20)
==5488== Address 0x402d04e is not stack'd, malloc'd or (recently) free'd
==5488==
==5488== Invalid read of size 1
==5488== at 0x4008575: mempcpy (mc_replace_strmem.c:677)
==5488== by 0x5368C2: _IO_file_xsputn@@GLIBC_2.1 (in /lib/libc-2.9.so)
==5488== by 0x50ED5C: vfprintf (in /lib/libc-2.9.so)
==5488== by 0x51591F: printf (in /lib/libc-2.9.so)
==5488== by 0x804856B: main (yliluku.c:20)
==5488== Address 0x402d02c is 0 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
==5488==
==5488== Invalid read of size 1
==5488== at 0x4008568: mempcpy (mc_replace_strmem.c:677)
==5488== by 0x5368C2: _IO_file_xsputn@@GLIBC_2.1 (in /lib/libc-2.9.so)
==5488== by 0x50ED5C: vfprintf (in /lib/libc-2.9.so)
==5488== by 0x51591F: printf (in /lib/libc-2.9.so)
==5488== by 0x804856B: main (yliluku.c:20)
==5488== Address 0x402d02d is 1 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
==5488==
==5488== Invalid read of size 1
==5488== at 0x4007453: strlen (mc_replace_strmem.c:242)
==5488== by 0x804859D: main (yliluku.c:23)
==5488== Address 0x402d02c is 0 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
--5488-- REDIR: 0x53d2b0 (free) redirected to 0x4005aa0 (free)
==5488==
==5488== ERROR SUMMARY: 181 errors from 11 contexts (suppressed: 14 from 1)
==5488==
==5488== 1 errors in context 1 of 11:
==5488== Invalid read of size 1
==5488== at 0x5367DC: _IO_file_xsputn@@GLIBC_2.1 (in /lib/libc-2.9.so)
==5488== by 0x50ED5C: vfprintf (in /lib/libc-2.9.so)
==5488== by 0x51591F: printf (in /lib/libc-2.9.so)
==5488== by 0x804856B: main (yliluku.c:20)
==5488== Address 0x402d04f is not stack'd, malloc'd or (recently) free'd
==5488==
==5488== 3 errors in context 2 of 11:
==5488== Invalid write of size 1
==5488== at 0x4007A57: memcpy (mc_replace_strmem.c:402)
==5488== by 0x8048545: main (yliluku.c:18)
==5488== Address 0x402d04c is not stack'd, malloc'd or (recently) free'd
==5488==
==5488== 8 errors in context 3 of 11:
==5488== Invalid write of size 1
==5488== at 0x4007A21: memcpy (mc_replace_strmem.c:402)
==5488== by 0x8048545: main (yliluku.c:18)
==5488== Address 0x402d02f is 3 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
==5488==
==5488== 8 errors in context 4 of 11:
==5488== Invalid write of size 1
==5488== at 0x4007A18: memcpy (mc_replace_strmem.c:402)
==5488== by 0x8048545: main (yliluku.c:18)
==5488== Address 0x402d02e is 2 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
==5488==
==5488== 8 errors in context 5 of 11:
==5488== Invalid write of size 1
==5488== at 0x4007A0F: memcpy (mc_replace_strmem.c:402)
==5488== by 0x8048545: main (yliluku.c:18)
==5488== Address 0x402d02d is 1 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
==5488==
==5488== 8 errors in context 6 of 11:
==5488== Invalid write of size 1
==5488== at 0x4007A07: memcpy (mc_replace_strmem.c:402)
==5488== by 0x8048545: main (yliluku.c:18)
==5488== Address 0x402d02c is 0 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
==5488==
==5488== 18 errors in context 7 of 11:
==5488== Invalid read of size 1
==5488== at 0x4008568: mempcpy (mc_replace_strmem.c:677)
==5488== by 0x5368C2: _IO_file_xsputn@@GLIBC_2.1 (in /lib/libc-2.9.so)
==5488== by 0x50ED5C: vfprintf (in /lib/libc-2.9.so)
==5488== by 0x51591F: printf (in /lib/libc-2.9.so)
==5488== by 0x804856B: main (yliluku.c:20)
==5488== Address 0x402d02d is 1 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
==5488==
==5488== 18 errors in context 8 of 11:
==5488== Invalid read of size 1
==5488== at 0x4008575: mempcpy (mc_replace_strmem.c:677)
==5488== by 0x5368C2: _IO_file_xsputn@@GLIBC_2.1 (in /lib/libc-2.9.so)
==5488== by 0x50ED5C: vfprintf (in /lib/libc-2.9.so)
==5488== by 0x51591F: printf (in /lib/libc-2.9.so)
==5488== by 0x804856B: main (yliluku.c:20)
==5488== Address 0x402d02c is 0 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
==5488==
==5488== 35 errors in context 9 of 11:
==5488== Invalid read of size 1
==5488== at 0x5367F4: _IO_file_xsputn@@GLIBC_2.1 (in /lib/libc-2.9.so)
==5488== by 0x50ED5C: vfprintf (in /lib/libc-2.9.so)
==5488== by 0x51591F: printf (in /lib/libc-2.9.so)
==5488== by 0x804856B: main (yliluku.c:20)
==5488== Address 0x402d04e is not stack'd, malloc'd or (recently) free'd
==5488==
==5488== 37 errors in context 10 of 11:
==5488== Invalid read of size 1
==5488== at 0x4007453: strlen (mc_replace_strmem.c:242)
==5488== by 0x804859D: main (yliluku.c:23)
==5488== Address 0x402d02c is 0 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
==5488==
==5488== 37 errors in context 11 of 11:
==5488== Invalid read of size 1
==5488== at 0x4007453: strlen (mc_replace_strmem.c:242)
==5488== by 0x50F4CF: vfprintf (in /lib/libc-2.9.so)
==5488== by 0x51591F: printf (in /lib/libc-2.9.so)
==5488== by 0x804856B: main (yliluku.c:20)
==5488== Address 0x402d02c is 0 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
--5488--
--5488-- supp: 14 dl-hack3-cond-1
==5488==
==5488== IN SUMMARY: 181 errors from 11 contexts (suppressed: 14 from 1)
==5488==
==5488== malloc/free: in use at exit: 4 bytes in 1 blocks.
==5488== malloc/free: 1 allocs, 0 frees, 4 bytes allocated.
==5488==
==5488== searching for pointers to 1 not-freed blocks.
==5488== checked 48,172 bytes.
==5488==
==5488==
==5488== 4 bytes in 1 blocks are definitely lost in loss record 1 of 1
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)
==5488==
==5488== LEAK SUMMARY:
==5488== definitely lost: 4 bytes in 1 blocks.
==5488== possibly lost: 0 bytes in 0 blocks.
==5488== still reachable: 0 bytes in 0 blocks.
==5488== suppressed: 0 bytes in 0 blocks.
--5488-- memcheck: sanity checks: 0 cheap, 1 expensive
--5488-- memcheck: auxmaps: 0 auxmap entries (0k, 0M) in use
--5488-- memcheck: auxmaps_L1: 0 searches, 0 cmps, ratio 0:10
--5488-- memcheck: auxmaps_L2: 0 searches, 0 nodes
--5488-- memcheck: SMs: n_issued = 9 (144k, 0M)
--5488-- memcheck: SMs: n_deissued = 0 (0k, 0M)
--5488-- memcheck: SMs: max_noaccess = 65535 (1048560k, 1023M)
--5488-- memcheck: SMs: max_undefined = 0 (0k, 0M)
--5488-- memcheck: SMs: max_defined = 25 (400k, 0M)
--5488-- memcheck: SMs: max_non_DSM = 9 (144k, 0M)
--5488-- memcheck: max sec V bit nodes: 0 (0k, 0M)
--5488-- memcheck: set_sec_vbits8 calls: 0 (new: 0, updates: 0)
--5488-- memcheck: max shadow mem size: 448k, 0M
--5488-- translate: fast SP updates identified: 1,765 ( 89.8%)
--5488-- translate: generic_known SP updates identified: 108 ( 5.4%)
--5488-- translate: generic_unknown SP updates identified: 92 ( 4.6%)
--5488-- tt/tc: 3,939 tt lookups requiring 3,969 probes
--5488-- tt/tc: 3,939 fast-cache updates, 3 flushes
--5488-- transtab: new 1,840 (39,574 -> 566,109; ratio 143:10) [0 scs]
--5488-- transtab: dumped 0 (0 -> ??)
--5488-- transtab: discarded 5 (113 -> ??)
--5488-- scheduler: 23,126 jumps (bb entries).
--5488-- scheduler: 0/2,143 major/minor sched events.
--5488-- sanity: 1 cheap, 1 expensive checks.
--5488-- exectx: 769 lists, 207 contexts (avg 0 per list)
--5488-- exectx: 397 searches, 216 full compares (544 per 1000)
--5488-- exectx: 0 cmp2, 397 cmp4, 0 cmpAll
--5488-- errormgr: 22 supplist searches, 981 comparisons during search
--5488-- errormgr: 195 errlist searches, 507 comparisons during search

Oh Hoh... johan paukahti.

Ensin näemme nipun valgrindin käynnistystietoja, kuten peruskäskyjen uudelleenohjauksen. Sitten alkaa varsinaiset tuotokset minun koodini osalta. Ensin nippu kirjoituksia häröosoitteisiin

==5488== Invalid write of size 1
==5488== at 0x4007A07: memcpy (mc_replace_strmem.c:402)
==5488== by 0x8048545: main (yliluku.c:18)
==5488== Address 0x402d02c is 0 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)

ja kumppanit. Tarkataanpa tätä hetki. Ensin on kerrottu mikä vika on löydetty. Eli kuten jo totesin, häröosoitteeseen kirjoitus, kirjoitettavan datan ollessa 1 tavu.
Sitten call trace kohdasta jossa ylikirjoitus tapahtui. Eli main() funktiosta riviltä 18 alkoi kutsujen nippu, joka päättyi ylikirjoitukseen memcpy() funktiossa.

memcpy(taulu2,taulukko,taulun_koko);


Ja viimeiset pari riviä kertovat kirjoituksen osuneen heti rivillä 14 allokoidun muistipalan perään.

Eli olemme siis ylikeirjoittaneet memcpy lausekkeessamme taulu2 viimeisen indeksin yli...

Mutta miksi?
Vastauksen kerron lopussa ;)

Skipataanpa muiden memcpy:stä tulleiden varoitusten ohi (oh, tämä muuten näyttää sille, että memcpy kirjoitti datan tavu kerrallaan... Aika yllätys minulle). Seuraavaksi tuleekin vastaan Invalid Read:eja

==5488== Invalid read of size 1
==5488== at 0x4007453: strlen (mc_replace_strmem.c:242)
==5488== by 0x50F4CF: vfprintf (in /lib/libc-2.9.so)
==5488== by 0x51591F: printf (in /lib/libc-2.9.so)
==5488== by 0x804856B: main (yliluku.c:20)
==5488== Address 0x402d02c is 0 bytes after a block of size 4 alloc'd
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)

Jälleen ensimmäisenä on tapahtunut virhe, eli luku häröosoitteesta. Sitten jälleen calltrace, ja lähellä majailevan allokoidun muistialueen allokointikohta. Eli rivin 20 printti on siis käyttänyt sisällään strlen() funktiota (tuntuu loogiselta, printti halunnee tietää kuinka pitkästi dataa on printattava käytettäessa %s muotoilua). strlen funktio puolestaan on lukenut yli taulu2 lopun. Toisin sanoen taulu2 muuttujamme ei ole ollut kunnolla "NULL terminoitu", eli ei ole sisältänyt viimeistä NULL merkkiä, ilmoittamassa tekstistringin loppumisesta. Ihan luonnollista koska aiemmin memcpyssä kirjoitimme taulukon lopun yli...

No nyt on hyvä hetki näyttää myös valgrindin heikkous. Eli ensimmäinen tapahtunut virhe jäi valgrindilta huomaamatta.

Rivillä 17 (tarkistettaessa taulukko taulukossa olleen tekstistringin pituutta strlen() funktiolla), on ensimmäisen kerran suoritettu luku väärästä paikasta. Ylempänä kopioitaessa tekstiä taulukko muuttujaan, kopioimme koko taulukon mitalta - siis myös viimeisen NULL merkin yli. seuraava strlen() lukee taulukko[0]:n osoitteesta alkaen kunnes löytää '\0' merkin. Koska kirjoitimme juuri sen yli, strlen lukee iloisesti yli taulukko muuttujamme rajojen, saaden stringin pituudeksi huomattavasti pidemmän pätkän kuin pitäisi. Ilmeisesti kuitenkin tämä luku sattui testiprosessimme stackin alueelle, sillä valgrind ei huomannut sitä. Nyt seuraava memcpy kopioi kuitenkin strlen() ilmoittaman (liian pitkän) pituuden verran dataa, joten loppuosa kopioinnista menee taulu2 rajojen yli. Tästä siis valgrindin ensimmäinen herja.

Loppu onkin jo itsestään selvää. Eli printatessamme taulukko ja taulu2 muuttujien sisällöt tekstinä, printf:n kutsuma strlen() lukee jälleen yli rajojen. Ja kaiken kruunaa vielä valgrind raportin lopussa oleva:

==5488== 4 bytes in 1 blocks are definitely lost in loss record 1 of 1
==5488== at 0x4006D3E: malloc (vg_replace_malloc.c:207)
==5488== by 0x80484E6: main (yliluku.c:14)

Eli allokoidun muistin vapauttaminen pääsi unohtumaan... ;)