Forum > FPC development
unit heaptrc does not write its report when STDERR is redirected
(1/1)
bodo-hugo-barwich:
Coming from this issue:
Memory Leak in fptest Unit
I found that the Unit heaptrc does not write its report when the STDERR is redirected.
The normal behaviour is that heaptrc write its report to STDERR
as seen in this strace log:
$ strace -f -o strace_demo_2020-10-22-2.log ./demo_hash-lists.run
Key: 'gob': 'gob_value'
Key: 'bog': 'bog_value'
Key: 'bob': ''
hsh map (cnt: '2'):
str map 'es' (cnt: '4'):
; key: 'key6' => 'value6'; key: 'bog' => 'bog_value'; key: 'gob' => 'gob_value'; key: 'trying a somwhat very long key 1' => 'inserting it's somewhat very long value 1'
str map 'en' (cnt: '3'):
; key: 'ab' => 'cd'; key: 'ij' => 'kl'; key: 'ef' => 'gh'
Heap dump by heaptrc unit
66 memory blocks allocated : 3144/3168
66 memory blocks freed : 3144/3168
0 unfreed memory blocks : 0
True heap size : 131072
True free heap : 131072
produces this strace activity log:
$ grep -ni "" strace_demo_2020-10-22-2.log
1:2581 execve("./demo_hash-lists.run", ["./demo_hash-lists.run"], 0x7ffd15c72448 /* 46 vars */) = 0
2:2581 getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
3:2581 rt_sigaction(SIGFPE, {sa_handler=0x4244e0, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x4026b0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8 ) = 0
4:2581 rt_sigaction(SIGSEGV, {sa_handler=0x4244e0, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x4026b0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8 ) = 0
5:2581 rt_sigaction(SIGBUS, {sa_handler=0x4244e0, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x4026b0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8 ) = 0
6:2581 rt_sigaction(SIGILL, {sa_handler=0x4244e0, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x4026b0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8 ) = 0
7:2581 ioctl(1, TCGETS, {B38400 opost isig icanon echo ...}) = 0
8:2581 ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
9:2581 ioctl(1, TCGETS, {B38400 opost isig icanon echo ...}) = 0
10:2581 ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
11:2581 readlink("/proc/self/exe", "/home/bodo/Projekte/pascal/hash-"..., 255) = 57
12:2581 open("/etc/timezone", O_RDONLY|O_LARGEFILE) = 3
13:2581 read(3, "Atlantic/Canary\n", 255) = 16
14:2581 close(3) = 0
15:2581 open("/usr/share/zoneinfo/Atlantic/Canary", O_RDONLY|O_LARGEFILE) = 3
16:2581 read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\6\0\0\0\0"..., 2048) = 1911
17:2581 mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfdaefe000
18:2581 mmap(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfdaef6000
19:2581 mmap(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfdaeee000
20:2581 close(3) = 0
21:2581 time([1603402165 /* 2020-10-22T22:29:25+0100 */]) = 1603402165 (2020-10-22T22:29:25+0100)
22:2581 mmap(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfdaee6000
23:2581 mmap(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfdaede000
24:2581 mmap(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfdaed6000
25:2581 mmap(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fcfdaece000
26:2581 write(1, "Key: 'gob': '", 13) = 13
27:2581 write(1, "gob_value", 9) = 9
28:2581 write(1, "'\n", 2) = 2
29:2581 write(1, "Key: 'bog': '", 13) = 13
30:2581 write(1, "bog_value", 9) = 9
31:2581 write(1, "'\n", 2) = 2
32:2581 write(1, "Key: 'bob': '", 13) = 13
33:2581 write(1, "'\n", 2) = 2
34:2581 write(1, "hsh map (cnt: '2'):\n", 20) = 20
35:2581 write(1, "str map 'es' (cnt: '4'):\n", 25) = 25
36:2581 write(1, "; key: 'key6' => 'value6'", 25) = 25
37:2581 write(1, "; key: 'bog' => 'bog_value'", 27) = 27
38:2581 write(1, "; key: 'gob' => 'gob_value'", 27) = 27
39:2581 write(1, "; key: 'trying a somwhat very lo"..., 88) = 88
40:2581 write(1, "\n", 1) = 1
41:2581 write(1, "str map 'en' (cnt: '3'):\n", 25) = 25
42:2581 write(1, "; key: 'ab' => 'cd'", 19) = 19
43:2581 write(1, "; key: 'ij' => 'kl'", 19) = 19
44:2581 write(1, "; key: 'ef' => 'gh'", 19) = 19
45:2581 write(1, "\n", 1) = 1
46:2581 munmap(0x7fcfdaefe000, 262144) = 0
47:2581 munmap(0x7fcfdaef6000, 32768) = 0
48:2581 munmap(0x7fcfdaeee000, 32768) = 0
49:2581 write(2, "Heap dump by heaptrc unit\n", 26) = 26
50:2581 write(2, "66 memory blocks allocated : 314"..., 39) = 39
51:2581 write(2, "66 memory blocks freed : 314"..., 39) = 39
52:2581 write(2, "0 unfreed memory blocks : 0\n", 28) = 28
53:2581 write(2, "True heap size : 131072", 23) = 23
54:2581 write(2, "\n", 1) = 1
55:2581 write(2, "True free heap : 131072\n", 24) = 24
56:2581 munmap(0x7fcfdaee6000, 32768) = 0
57:2581 munmap(0x7fcfdaede000, 32768) = 0
58:2581 munmap(0x7fcfdaed6000, 32768) = 0
59:2581 munmap(0x7fcfdaece000, 32768) = 0
60:2581 exit_group(0) = ?
61:2581 +++ exited with 0 +++
Between lines 49 - 54 it shows that the Report is written to STDERR
Now redirecting the STDERR this whole section is missing:
$ strace -f -o strace_demo_2020-10-22-1.log ./demo_hash-lists.run 2>demo_error.log 1>demo_report.log
$ grep -ni "" strace_demo_2020-10-22-1.log
1:2566 execve("./demo_hash-lists.run", ["./demo_hash-lists.run"], 0x7fffb7d8b7d8 /* 46 vars */) = 0
2:2566 getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
3:2566 rt_sigaction(SIGFPE, {sa_handler=0x4244e0, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x4026b0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8 ) = 0
4:2566 rt_sigaction(SIGSEGV, {sa_handler=0x4244e0, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x4026b0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8 ) = 0
5:2566 rt_sigaction(SIGBUS, {sa_handler=0x4244e0, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x4026b0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8 ) = 0
6:2566 rt_sigaction(SIGILL, {sa_handler=0x4244e0, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x4026b0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8 ) = 0
7:2566 ioctl(1, TCGETS, 0x7fffb4bf5f80) = -1 ENOTTY (Función ioctl no apropiada para el dispositivo)
8:2566 ioctl(2, TCGETS, 0x7fffb4bf5f80) = -1 ENOTTY (Función ioctl no apropiada para el dispositivo)
9:2566 ioctl(1, TCGETS, 0x7fffb4bf5f80) = -1 ENOTTY (Función ioctl no apropiada para el dispositivo)
10:2566 ioctl(2, TCGETS, 0x7fffb4bf5f80) = -1 ENOTTY (Función ioctl no apropiada para el dispositivo)
11:2566 readlink("/proc/self/exe", "/home/bodo/Projekte/pascal/hash-"..., 255) = 57
12:2566 open("/etc/timezone", O_RDONLY|O_LARGEFILE) = 3
13:2566 read(3, "Atlantic/Canary\n", 255) = 16
14:2566 close(3) = 0
15:2566 open("/usr/share/zoneinfo/Atlantic/Canary", O_RDONLY|O_LARGEFILE) = 3
16:2566 read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\6\0\0\0\0"..., 2048) = 1911
17:2566 mmap(NULL, 262144, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f15d6986000
18:2566 mmap(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f15d697e000
19:2566 mmap(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f15d6976000
20:2566 close(3) = 0
21:2566 time([1603401977 /* 2020-10-22T22:26:17+0100 */]) = 1603401977 (2020-10-22T22:26:17+0100)
22:2566 mmap(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f15d696e000
23:2566 mmap(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f15d6966000
24:2566 mmap(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f15d695e000
25:2566 mmap(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f15d6956000
26:2566 write(1, "Key: 'gob': 'gob_value'\nKey: 'bo"..., 256) = 256
27:2566 write(1, " very long value 1'\nstr map 'en'"..., 103) = 103
28:2566 munmap(0x7f15d6986000, 262144) = 0
29:2566 munmap(0x7f15d697e000, 32768) = 0
30:2566 munmap(0x7f15d6976000, 32768) = 0
31:2566 munmap(0x7f15d696e000, 32768) = 0
32:2566 munmap(0x7f15d6966000, 32768) = 0
33:2566 munmap(0x7f15d695e000, 32768) = 0
34:2566 munmap(0x7f15d6956000, 32768) = 0
35:2566 exit_group(0) = ?
36:2566 +++ exited with 0 +++
Between lines 31 and 32 the heaptrc is expected but it simply does not happen.
This issue is especially relevant because it hinders any use of heaptrc in any reliable CI pipeline.
I like this feature very much because it helps to develop solid and reliable applications. I would not like just to disable it because the code quality would suffer.
bodo-hugo-barwich:
I figured out a Workaround which works quite nice.
According to the HeapTrc at:
HeapTrc Environment Variables
--- Code: Text [+][-]window.onload = function(){var x1 = document.getElementById("main_content_section"); if (x1) { var x = document.getElementsByClassName("geshi");for (var i = 0; i < x.length; i++) { x[i].style.maxHeight='none'; x[i].style.height = Math.min(x[i].clientHeight+15,306)+'px'; x[i].style.resize = "vertical";}};} --- #Execute the Demo Application echo "Demo Application: Executing ..." export HEAPTRC="log=demo_heap.log"; ./demo_hash-lists.dbg.run 2>./demo_error.log 1>./demo_exec.log ; error_code=$? echo "Demo Application: Execution finished with [$error_code]" #Demo Application Execution Report echo "Demo Execution Log:" ; cat ./demo_exec.log echo "Demo Execution Error:" ; cat ./demo_error.log echo "Demo Execution Heap:" ; cat ./demo_heap.log error=`cat ./demo_error.log` ; if [ -n "$error" ]; then echo "Demo failed with Error [Code: '$error_code']" && exit 1; fi ; leak=`cat ./demo_heap.log | grep -i "unfreed memory blocks" | awk '{print $1}'` ; if [ $leak -ne 0 ]; then echo "Memory Leaks: $leak" && exit 1; else echo "Memory Leaks: NONE"; fi ;
This enables me to check for Memory Leaks and possible Execution Errors while nicely documenting the Test Suite Execution.
This produces a nice Report:
GitHub Workflow Report
Demo Application: Executing ...
Demo Application: Execution finished with [ 0 ]
Demo Execution Log:
Key: 'gob': 'gob_value'
Key: 'bog': 'bog_value'
Key: 'bob': ''
hsh map (cnt: '2'):
str map 'es' (cnt: '4'):
; key: 'key6' => 'value6'; key: 'bog' => 'bog_value'; key: 'gob' => 'gob_value'; key: 'trying a somwhat very long key 1' => 'inserting its somewhat very long value 1'
str map 'en' (cnt: '3'):
; key: 'ab' => 'cd'; key: 'ij' => 'kl'; key: 'ef' => 'gh'
Demo Execution Error:
Demo Execution Heap:
/home/runner/work/hash-lists/hash-lists/demo_hash-lists.dbg.run
Heap dump by heaptrc unit
68 memory blocks allocated : 2662/2688
68 memory blocks freed : 2662/2688
0 unfreed memory blocks : 0
True heap size : 163840
True free heap : 163840
Memory Leaks: NONE
Application Tests: Executing ...
Application Tests: Tests finished with [ 0 ]
Tests Execution Log:
FPTest / Testing
.......
Time: 00:00:00.001
OK: 7 tests
Tests Execution Error:
Tests Execution Heap:
/home/runner/work/hash-lists/hash-lists/tests/tests_hash-lists.dbg.run
Heap dump by heaptrc unit
636 memory blocks allocated : 31619/32944
635 memory blocks freed : 31611/32936
1 unfreed memory blocks : 8
True heap size : 458752
True free heap : 458592
Should be : 458616
Call trace for block $00007F6DCD6912A0 size 8
$00000000004ADB11 line 2258 of ../fptest/src/TestFramework.pas
$00000000004B19FF line 2705 of ../fptest/src/TestFramework.pas
$00000000004B0B46 line 2808 of ../fptest/src/TestFramework.pas
$00000000004B1222 line 2741 of ../fptest/src/TestFramework.pas
$00000000004B0B7F line 2810 of ../fptest/src/TestFramework.pas
$00000000004B986B line 3829 of ../fptest/src/TestFramework.pas
$000000000049A7C4 line 899 of ../fptest/src/TestFrameworkProxy.pas
$0000000000496DBF line 322 of ../fptest/src/TestFrameworkProxy.pas
Memory Leaks: NONE
I needed to ignore the Memory Leak in the fptest Unit but if this increases the Automated Tests will tell me right away.
Navigation
[0] Message Index