Re: [bug-gawk] Increased RAM memory usage in gawk 5.0.1 compared to gawk 4.1.4

[Andrew J. Schorr]

On Wed, Aug 28, 2019 at 05:57:05AM -0600, address@hidden wrote:
> Thanks for the report and the test case. I will work on it.

FYI, I ran 'valgrind --leak-check=full --show-leak-kinds=all' with and
without setting fixram=1. Without fixram=1, the summary is:

==18681== LEAK SUMMARY:
==18681==    definitely lost: 165,166,400 bytes in 14,747 blocks
==18681==    indirectly lost: 17,081,989 bytes in 1,461,920 blocks
==18681==      possibly lost: 1,186,710,647 bytes in 8,297,418 blocks
==18681==    still reachable: 125,889,900 bytes in 696,405 blocks
==18681==         suppressed: 0 bytes in 0 blocks

With fixram=1, I get:

==16885== LEAK SUMMARY:
==16885==    definitely lost: 0 bytes in 0 blocks
==16885==    indirectly lost: 0 bytes in 0 blocks
==16885==      possibly lost: 1,097,104 bytes in 3,950 blocks
==16885==    still reachable: 245,737,975 bytes in 952,550 blocks
==16885==                       of which reachable via heuristic:
==16885==                         newarray           : 704 bytes in 8 blocks
==16885==         suppressed: 0 bytes in 0 blocks

I have to imagine that there's a reference counting issue with the
$1 field arising from 'mom_version !~ $1'. I see this in the
valgrind output when not setting fixram (note that purge_record never
appears in the valgrind log in the fixram=1 case):

bash-4.2$ grep -B4 purge_record nofixram.log
==18681== 33,600 bytes in 3 blocks are still reachable in loss record 496 of 563
==18681==    at 0x4C29BC3: malloc (vg_replace_malloc.c:299)
==18681==    by 0x45A285: emalloc_real (awk.h:1976)
==18681==    by 0x45A285: more_blocks (node.c:1052)
==18681==    by 0x44425E: purge_record (field.c:366)
--
==18681== 
==18681== 4,172,765 bytes in 204,707 blocks are still reachable in loss record 
529 of 563
==18681==    at 0x4C29BC3: malloc (vg_replace_malloc.c:299)
==18681==    by 0x4441F6: emalloc_real (awk.h:1976)
==18681==    by 0x4441F6: purge_record (field.c:360)
--
==18681== 
==18681== 5,440,399 bytes in 211,415 blocks are still reachable in loss record 
532 of 563
==18681==    at 0x4C29BC3: malloc (vg_replace_malloc.c:299)
==18681==    by 0x4441F6: emalloc_real (awk.h:1976)
==18681==    by 0x4441F6: purge_record (field.c:360)
--
==18681== 
==18681== 8,487,638 bytes in 727,789 blocks are indirectly lost in loss record 
535 of 563
==18681==    at 0x4C29BC3: malloc (vg_replace_malloc.c:299)
==18681==    by 0x4441F6: emalloc_real (awk.h:1976)
==18681==    by 0x4441F6: purge_record (field.c:360)
--
==18681== 
==18681== 8,594,351 bytes in 734,131 blocks are indirectly lost in loss record 
536 of 563
==18681==    at 0x4C29BC3: malloc (vg_replace_malloc.c:299)
==18681==    by 0x4441F6: emalloc_real (awk.h:1976)
==18681==    by 0x4441F6: purge_record (field.c:360)
--
==18681== 
==18681== 72,810,225 bytes in 3,693,203 blocks are possibly lost in loss record 
557 of 563
==18681==    at 0x4C29BC3: malloc (vg_replace_malloc.c:299)
==18681==    by 0x4441F6: emalloc_real (awk.h:1976)
==18681==    by 0x4441F6: purge_record (field.c:360)
--
==18681== 87,690,336 (79,464,000 direct, 8,226,336 indirect) bytes in 7,095 
blocks are definitely lost in loss record 558 of 563
==18681==    at 0x4C29BC3: malloc (vg_replace_malloc.c:299)
==18681==    by 0x45A285: emalloc_real (awk.h:1976)
==18681==    by 0x45A285: more_blocks (node.c:1052)
==18681==    by 0x44425E: purge_record (field.c:366)
--
==18681== 
==18681== 93,502,249 bytes in 3,848,554 blocks are possibly lost in loss record 
560 of 563
==18681==    at 0x4C29BC3: malloc (vg_replace_malloc.c:299)
==18681==    by 0x4441F6: emalloc_real (awk.h:1976)
==18681==    by 0x4441F6: purge_record (field.c:360)
--
==18681== 242,995,200 bytes in 21,696 blocks are possibly lost in loss record 
562 of 563
==18681==    at 0x4C29BC3: malloc (vg_replace_malloc.c:299)
==18681==    by 0x45A285: emalloc_real (awk.h:1976)
==18681==    by 0x45A285: more_blocks (node.c:1052)
==18681==    by 0x44425E: purge_record (field.c:366)

That gives a total of possibly or definitely lost due to purge_record:

bash-4.2$ grep -B4 purge_record nofixram.log | awk '/lost/ {s += gensub(/,/, 
"", "g", $2)} END {print s}'
514079999

And my RSS values are:
1676788 /home/users/schorr/src/awk/master/gawk -f test_ram.awk -v 
mibfile=10.220.33.18_153125.log.gz -v sqlrefmapfile=sqlRefMap.txt

261496 /home/users/schorr/src/awk/master/gawk -f test_ram.awk -v 
mibfile=10.220.33.18_153125.log.gz -v sqlrefmapfile=sqlRefMap.txt -v fix

So those purge_record losses seem to account for 35% of the problem.

No time to dig deeper at the moment...

Regards,
Andy