Merge: Basic Memory Profiler
authorJean Privat <jean@pryen.org>
Fri, 24 Jun 2016 19:19:04 +0000 (15:19 -0400)
committerJean Privat <jean@pryen.org>
Fri, 24 Jun 2016 19:19:04 +0000 (15:19 -0400)
Here a proof of concept of a basic memory profiler for Nit.
The approach is an option `--trace-memory` that generate a logger with the rest of the code.
Each allocation event produce a line in an time-stamped log file.

When compiling nitc with nitc, the generated log is 300MB. Quite big but manageable.
There is not a lot of optimizations, we let the libc cache the writing of the log.
So there is an overhead.

without `--trace-memory`:
* real 0m5.721s
* user 0m7.216s

with it
* real  0m8.730s (+52%, beause IO I think)
* user 0m9.600s (+33%)

To process the log file, a autonomous tool `memplot` is provided that is made of a nit converter to csv and a R plot script.
There is not a lot of usability, configuration is done by hacking the source code :)

Here a result for the nitc compilation

![memory](https://cloud.githubusercontent.com/assets/135828/16327063/245d273c-399a-11e6-82d3-950db85f7326.png)

The PR is divided into 3 parts:

* preparation of the infrastructure in the compiler (agnostic)
* extension of nitc that refines methods to add the logger
* the quick and dirty memplot tool

Pull-Request: #2200
Reviewed-by: Alexis Laferrière <alexis.laf@xymus.net>

contrib/memplot/memplot.nit [new file with mode: 0644]
contrib/memplot/memplot.r [new file with mode: 0644]
contrib/memplot/package.ini [new file with mode: 0644]
share/man/nitc.md
src/compiler/abstract_compiler.nit
src/compiler/compiler.nit
src/compiler/global_compiler.nit
src/compiler/memory_logger.nit [new file with mode: 0644]
src/compiler/separate_compiler.nit
src/compiler/separate_erasure_compiler.nit
src/interpreter/naive_interpreter.nit

diff --git a/contrib/memplot/memplot.nit b/contrib/memplot/memplot.nit
new file mode 100644 (file)
index 0000000..2bd1727
--- /dev/null
@@ -0,0 +1,198 @@
+# This file is part of NIT ( http://www.nitlanguage.org ).
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+# Program to transform `memory.log` files produced by `nitc --trace-memory` into a csv file
+module memplot
+
+import counter
+import template
+
+# An aggregated time-slice
+class Aggreg
+       # The start time of the slice
+       var time: Float
+
+       # Number of allocations
+       var acpt = new Counter[String]
+
+       # Number of allocated bytes
+       var asiz = new Counter[String]
+
+       # Number of deallocations
+       var dcpt = new Counter[String]
+
+       # Number of deallocated bytes
+       var dsiz = new Counter[String]
+
+       # Total number of allocations since the beginning
+       var cpttot = new Counter[String]
+
+       # Total number of allocated bytes since the beginning
+       var siztot = new Counter[String]
+
+       # Map of all the various counters.
+       var fields = new Map[String, Counter[String]]
+
+       init do
+               fields["acpt"] = acpt
+               fields["asiz"] = asiz
+               fields["dcpt"] = dcpt
+               fields["dsiz"] = dsiz
+               fields["cpttot"] = cpttot
+               fields["siztot"] = siztot
+       end
+end
+
+# Main class that does the job
+class MemProg
+       # The `memory.log` file.
+       var filepath: String
+
+       # The delay of an aggregation
+       var time_slice: Float
+
+       # Total number of events
+       var events = 0
+
+       # List a all time aggregations
+       var aggregs = new Array[Aggreg]
+
+       # Total number of allocations
+       var cpttot = new Counter[String]
+
+       # Total number of allocated bytes
+       var siztot = new Counter[String]
+
+       # Parse the log file `filepath` and fill `aggregs`.
+       fun parse do
+               # Current lines (not yet put in an aggreg)
+               var lines = new Counter[String]
+
+               var time = 0.0
+               var dt = 100.0
+               dt = 100.0
+               for l in "memory.log".to_path.each_line do
+                       if l[0] == '#' then
+                               var t = l.substring_from(2).to_f
+
+                               while t > time + dt do
+                                       aggreg(lines, time)
+                                       time += dt
+                               end
+                               #if time > 1000.0 then break
+                               continue
+                       end
+                       events += 1
+                       lines.inc(l)
+               end
+               aggreg(lines, time)
+       end
+
+       # Create and register a new aggregation
+       fun aggreg(lines: Counter[String], t1: Float) do
+               var aggreg = new Aggreg(t1)
+               aggregs.add aggreg
+               print "events:{events} aggregs:{aggregs.length} {t1}ms"
+
+               # Process each distinct line
+               for l, v in lines do
+                       var a = l.split('\t')
+                       if a.length != 3 then
+                               print "Error {a.length}. {l}"
+                               continue
+                       end
+                       var c = a[0]
+                       var s = a[1].to_i
+                       var e = a[2]
+                       if c == "+" then
+                               aggreg.acpt[e] += v
+                               aggreg.asiz[e] += v * s
+                       else if c == "-" then
+                               aggreg.dcpt[e] += v
+                               aggreg.dsiz[e] += v * s
+                       else abort
+               end
+               lines.clear
+
+               # Sum all information
+               for e, v in aggreg.acpt do cpttot[e] += v
+               for e, v in aggreg.asiz do siztot[e] += v
+               for e, v in aggreg.dcpt do cpttot[e] -= v
+               for e, v in aggreg.dsiz do siztot[e] -= v
+
+               # Copy current total
+               aggreg.cpttot.add_all cpttot
+               aggreg.siztot.add_all siztot
+
+               cpttot.print_elements(2)
+       end
+
+       # Generate a *long* CVS file, to use with statistical tools
+       fun tolong: Writable
+       do
+               var res = new Template
+
+               # Write the header
+               res.add "time, class"
+               for f, c in aggregs.first.fields do
+                       res.add ", "
+                       res.add f
+               end
+               res.add "\n"
+
+               # Collect the largest tags, add add an `other` tag.
+               var elts = siztot.sort.reversed.sub(0,10).reversed
+               elts.add "other"
+
+               for a in aggregs do
+                       var t = a.time.to_s
+
+                       # For each field compute the value of `other`
+                       for f, c in a.fields do
+                               var o = c.sum
+                               for e in elts do
+                                       if e == "other" then continue
+                                       o -= c[e]
+                               end
+                               c["other"] = o
+                       end
+
+                       # For each tag (incl. other) produce a line
+                       for e in elts do
+                               res.add t
+                               res.add ", "
+                               res.add e
+
+                               for f, v in a.fields do
+                                       res.add ", "
+                                       res.add v[e].to_s
+                               end
+                               res.add "\n"
+                       end
+               end
+               return res
+       end
+end
+
+var m = new MemProg("memory.log", 100.0)
+m.parse
+
+m.cpttot.print_summary
+m.siztot.print_summary
+
+m.tolong.write_to_file "memory.csv"
+
+if "memplot.r".file_exists then
+       system("r memplot.r")
+end
diff --git a/contrib/memplot/memplot.r b/contrib/memplot/memplot.r
new file mode 100644 (file)
index 0000000..adda5b8
--- /dev/null
@@ -0,0 +1,29 @@
+# This file is part of NIT ( http://www.nitlanguage.org ).
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+# R program to draw a nice plot diagram
+
+mem <- read.csv("memory.csv")
+
+library(ggplot2)
+
+order <- rev(unique(mem$class))
+
+ggplot(mem, aes(x=time, y=siztot, fill=class)) +
+       geom_area(color='black', size=0.02) +
+       scale_fill_brewer(palette="Spectral", breaks=order) +
+       theme(legend.text=element_text(size=7))
+
+ggsave("memory.pdf")
+ggsave("memory.png")
diff --git a/contrib/memplot/package.ini b/contrib/memplot/package.ini
new file mode 100644 (file)
index 0000000..fa7a860
--- /dev/null
@@ -0,0 +1,11 @@
+[package]
+name=memplot
+tags=devel
+maintainer=Jean Privat <jean@pryen.org>
+license=Apache-2.0
+[upstream]
+browse=https://github.com/nitlang/nit/tree/master/contrib/memplot/
+git=https://github.com/nitlang/nit.git
+git.directory=contrib/memplot/
+homepage=http://nitlanguage.org
+issues=https://github.com/nitlang/nit/issues
index a316782..77c8aa8 100644 (file)
@@ -374,9 +374,6 @@ Disable implicit casts on unsafe return with erasure-typing policy (dangerous).
 These options are used to debug or to bench the compilation results.
 Usually you do not need them since they make the generated code slower.
 
-### `--hardening`
-Generate contracts in the C code against bugs in the compiler.
-
 ### `--no-shortcut-range`
 Always instantiate a range and its iterator on 'for' loops.
 
@@ -408,7 +405,35 @@ Disable advanced gcc directives for optimization.
 ### `--trampoline-call`
 Use an indirection when calling.
 
-Just add the trampolines of `--substitute-monomorph` without doing any additionnal optimizations.
+Just add the trampolines of `--substitute-monomorph` without doing any additional optimizations.
+
+
+### DEBUGGING
+
+### `--no-stacktrace`
+Disable the generation of stack traces.
+
+With this option, the compiled program will not display stack traces on runtime errors.
+
+Because stack traces rely on libunwind, this option might be useful in order to generate more portable binaries
+since libunwind might be non available on the runtime system (or available with an ABI incompatible version).
+
+The generated C is API-portable and can be reused, distributed and compiled on any supported system.
+If the option `--no-stacktrace` is not used but the development files of the library `libunwind` are not available, then a warning will be displayed
+and stack trace will be disabled.
+
+Note that the `--no-stacktrace` option (or this absence) can be toggled manually in the generated Makefile (search `NO_STACKTRACE` in the Makefile).
+Moreover, the environment variable `NIT_NO_STACK` (see bellow) can also be used at runtime to disable stack traces.
+
+### `--trace-memory`
+Enable dynamic measure of memory usage.
+
+Compiled programs will generate a large `memory.log` file that logs all memory allocations.
+This logs file can then be analyzed with the tool `memplot` from contrib.
+
+### `--hardening`
+Generate contracts in the C code against bugs in the compiler.
+
 
 ## INTERNAL OPTIONS
 
@@ -430,21 +455,6 @@ Do not check, and produce errors, on visibility issues.
 ### `--no-main`
 Do not generate main entry point.
 
-### `--no-stacktrace`
-Disable the generation of stack traces.
-
-With this option, the compiled program will not display stack traces on runtime errors.
-
-Because stack traces rely on libunwind, this option might be useful in order to generate more portable binaries
-since libunwind might be non available on the runtime system (or available with an ABI incompatible version).
-
-The generated C is API-portable and can be reused, distributed and compiled on any supported system.
-If the option `--no-stacktrace` is not used but the development files of the library `libunwind` are not available, then a warning will be displayed
-and stack trace will be disabled.
-
-Note that the `--no-stacktrace` option (or this absence) can be toggled manually in the generated Makefile (search `NO_STACKTRACE` in the Makefile).
-Moreover, the environment variable `NIT_NO_STACK` (see bellow) can also be used at runtime to disable stack traces.
-
 ### `--max-c-lines`
 Maximum number of lines in generated C files. Use 0 for unlimited.
 
index 0fa3d4b..cddc8d3 100644 (file)
@@ -779,6 +779,20 @@ extern void nitni_global_ref_decr( struct nitni_ref *ref );
                v.add "\}"
        end
 
+       # Hook to add specif piece of code before the the main C function.
+       #
+       # Is called by `compile_main_function`
+       fun compile_before_main(v: VISITOR)
+       do
+       end
+
+       # Hook to add specif piece of code at the begin on the main C function.
+       #
+       # Is called by `compile_main_function`
+       fun compile_begin_main(v: VISITOR)
+       do
+       end
+
        # Generate the main C function.
        #
        # This function:
@@ -876,12 +890,16 @@ extern void nitni_global_ref_decr( struct nitni_ref *ref );
                v.add_decl("exit(status);")
                v.add_decl("\}")
 
+               compile_before_main(v)
+
                if no_main then
                        v.add_decl("int nit_main(int argc, char** argv) \{")
                else
                        v.add_decl("int main(int argc, char** argv) \{")
                end
 
+               compile_begin_main(v)
+
                v.add "#if !defined(__ANDROID__) && !defined(TARGET_OS_IPHONE)"
                v.add("signal(SIGABRT, sig_handler);")
                v.add("signal(SIGFPE, sig_handler);")
@@ -1208,8 +1226,6 @@ abstract class AbstractCompilerVisitor
 
        fun native_array_instance(elttype: MType, length: RuntimeVariable): RuntimeVariable is abstract
 
-       fun calloc_array(ret_type: MType, arguments: Array[RuntimeVariable]) is abstract
-
        fun native_array_def(pname: String, ret_type: nullable MType, arguments: Array[RuntimeVariable]): Bool do return false
 
        # Return an element of a native array.
@@ -1220,6 +1236,16 @@ abstract class AbstractCompilerVisitor
        # The method is unsafe and is just a direct wrapper for the specific implementation of native arrays
        fun native_array_set(native_array: RuntimeVariable, index: Int, value: RuntimeVariable) is abstract
 
+       # Allocate `size` bytes with the low_level `nit_alloc` C function
+       #
+       # This method can be redefined to inject statistic or tracing code.
+       #
+       # `tag` if any, is used to mark the class of the allocated object.
+       fun nit_alloc(size: String, tag: nullable String): String
+       do
+               return "nit_alloc({size})"
+       end
+
        # Evaluate `args` as expressions in the call of `mpropdef` on `recv`.
        # This method is used to manage varargs in signatures and returns the real array
        # of runtime variables to use in the call.
@@ -2551,7 +2577,8 @@ redef class AMethPropdef
                                v.ret(v.new_expr("!{res}", ret.as(not null)))
                                return true
                        else if pname == "new" then
-                               v.ret(v.new_expr("(char*)nit_alloc({arguments[1]})", ret.as(not null)))
+                               var alloc = v.nit_alloc(arguments[1].to_s, "NativeString")
+                               v.ret(v.new_expr("(char*){alloc}", ret.as(not null)))
                                return true
                        else if pname == "fetch_4_chars" then
                                v.ret(v.new_expr("(long)*((uint32_t*)({arguments[0]} + {arguments[1]}))", ret.as(not null)))
@@ -3004,12 +3031,6 @@ redef class AMethPropdef
                else if pname == "sys" then
                        v.ret(v.new_expr("glob_sys", ret.as(not null)))
                        return true
-               else if pname == "calloc_string" then
-                       v.ret(v.new_expr("(char*)nit_alloc({arguments[1]})", ret.as(not null)))
-                       return true
-               else if pname == "calloc_array" then
-                       v.calloc_array(ret.as(not null), arguments)
-                       return true
                else if pname == "object_id" then
                        v.ret(v.new_expr("(long){arguments.first}", ret.as(not null)))
                        return true
index c013295..3c0ab59 100644 (file)
@@ -18,6 +18,7 @@ module compiler
 import separate_erasure_compiler
 import global_compiler
 import compiler_ffi
+import memory_logger
 
 import platform::android
 import platform::pnacl
index 0ac6e66..628e78a 100644 (file)
@@ -426,11 +426,6 @@ class GlobalCompilerVisitor
                self.add("{recv}[{i}]={val};")
        end
 
-       redef fun calloc_array(ret_type, arguments)
-       do
-               self.ret(self.new_expr("NEW_{ret_type.c_name}({arguments[1]})", ret_type))
-       end
-
        redef fun send(m, args)
        do
                var types = self.collect_types(args.first)
diff --git a/src/compiler/memory_logger.nit b/src/compiler/memory_logger.nit
new file mode 100644 (file)
index 0000000..1f96451
--- /dev/null
@@ -0,0 +1,76 @@
+# This file is part of NIT ( http://www.nitlanguage.org ).
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+# Extension to inject memory-tracing instrumentation in code generated by `nitc`.
+module memory_logger
+
+import abstract_compiler
+
+redef class ToolContext
+       # --trace-memory
+       var opt_trace_memory = new OptionBool("Enable dynamic measure of memory usage", "--trace-memory")
+
+       init do
+               self.option_context.add_option opt_trace_memory
+       end
+end
+
+redef class AbstractCompiler
+       redef fun compile_before_main(v)
+       do
+               super
+
+               if not modelbuilder.toolcontext.opt_trace_memory.value then return
+
+               header.add_decl("#include <time.h>")
+               header.add_decl("extern FILE *mlog;")
+               header.add_decl("extern struct timespec mlog_last;")
+               header.add_decl("extern struct timespec mlog_time0;")
+               v.add_decl("FILE *mlog;")
+               v.add_decl("struct timespec mlog_last;")
+               v.add_decl("struct timespec mlog_time0;")
+       end
+
+       redef fun compile_begin_main(v)
+       do
+               super
+
+               if not modelbuilder.toolcontext.opt_trace_memory.value then return
+
+               v.add("mlog = fopen(\"memory.log\", \"w\");")
+               v.add("clock_gettime(CLOCK_MONOTONIC, &mlog_time0);")
+       end
+end
+
+redef class AbstractCompilerVisitor
+       redef fun nit_alloc(size, tag)
+       do
+               if not compiler.modelbuilder.toolcontext.opt_trace_memory.value then return super
+
+               # Log time each 10ms (ie 1e7ns)
+               var tw = get_name("mtw")
+               add_decl("struct timespec {tw};")
+               add("clock_gettime(CLOCK_MONOTONIC, &{tw});")
+               add("if(mlog_last.tv_sec < {tw}.tv_sec || mlog_last.tv_nsec + 1e7 < {tw}.tv_nsec) \{")
+               add("mlog_last = {tw};")
+               add("fprintf(mlog, \"# %f\\n\", 1000.0*{tw}.tv_sec + 1e-6*{tw}.tv_nsec - (1000.0*mlog_time0.tv_sec + 1e-6*mlog_time0.tv_nsec));")
+               add("\}")
+
+               # Print size and tag the mlog
+               var str = "\"+\\t%d\\t%s\\n\", {size}, \"{tag or else "?"}\""
+               add("fprintf(mlog, {str});")
+
+               return super
+       end
+end
index 362bb52..63f5517 100644 (file)
@@ -877,7 +877,8 @@ class SeparateCompiler
                        self.provide_declaration("BOX_{c_name}", "val* BOX_{c_name}({mtype.ctype_extern});")
                        v.add_decl("/* allocate {mtype} */")
                        v.add_decl("val* BOX_{mtype.c_name}({mtype.ctype_extern} value) \{")
-                       v.add("struct instance_{c_name}*res = nit_alloc(sizeof(struct instance_{c_name}));")
+                       var alloc = v.nit_alloc("sizeof(struct instance_{c_name})", mclass.full_name)
+                       v.add("struct instance_{c_name}*res = {alloc};")
                        v.compiler.undead_types.add(mtype)
                        v.require_declaration("type_{c_name}")
                        v.add("res->type = &type_{c_name};")
@@ -899,7 +900,8 @@ class SeparateCompiler
                        else
                                var res = v.new_named_var(mtype, "self")
                                res.is_exact = true
-                               v.add("{res} = nit_alloc(sizeof(struct instance_{mtype.c_name}));")
+                               alloc = v.nit_alloc("sizeof(struct instance_{mtype.c_name})", mclass.full_name)
+                               v.add("{res} = {alloc};")
                                v.add("{res}->type = type;")
                                hardening_live_type(v, "type")
                                v.require_declaration("class_{c_name}")
@@ -926,7 +928,8 @@ class SeparateCompiler
                        var res = v.get_name("self")
                        v.add_decl("struct instance_{c_name} *{res};")
                        var mtype_elt = mtype.arguments.first
-                       v.add("{res} = nit_alloc(sizeof(struct instance_{c_name}) + length*sizeof({mtype_elt.ctype}));")
+                       var alloc = v.nit_alloc("sizeof(struct instance_{c_name}) + length*sizeof({mtype_elt.ctype})", mclass.full_name)
+                       v.add("{res} = {alloc};")
                        v.add("{res}->type = type;")
                        hardening_live_type(v, "type")
                        v.require_declaration("class_{c_name}")
@@ -949,7 +952,8 @@ class SeparateCompiler
                        else
                                var res = v.new_named_var(mtype, "self")
                                res.is_exact = true
-                               v.add("{res} = nit_alloc(sizeof(struct instance_{pointer_type.c_name}));")
+                               var alloc = v.nit_alloc("sizeof(struct instance_{pointer_type.c_name})", mclass.full_name)
+                               v.add("{res} = {alloc};")
                                v.add("{res}->type = type;")
                                hardening_live_type(v, "type")
                                v.require_declaration("class_{c_name}")
@@ -972,9 +976,11 @@ class SeparateCompiler
                        res.is_exact = true
                        var attrs = self.attr_tables.get_or_null(mclass)
                        if attrs == null then
-                               v.add("{res} = nit_alloc(sizeof(struct instance));")
+                               var alloc = v.nit_alloc("sizeof(struct instance)", mclass.full_name)
+                               v.add("{res} = {alloc};")
                        else
-                               v.add("{res} = nit_alloc(sizeof(struct instance) + {attrs.length}*sizeof(nitattribute_t));")
+                               var alloc = v.nit_alloc("sizeof(struct instance) + {attrs.length}*sizeof(nitattribute_t)", mclass.full_name)
+                               v.add("{res} = {alloc};")
                        end
                        v.add("{res}->type = type;")
                        hardening_live_type(v, "type")
index 6f7d1e8..c370461 100644 (file)
@@ -657,11 +657,4 @@ class SeparateErasureCompilerVisitor
                self.add("{res} = NEW_{nclass.c_name}({length});")
                return res
        end
-
-       redef fun calloc_array(ret_type, arguments)
-       do
-               var ret = ret_type.as(MClassType)
-               self.require_declaration("NEW_{ret.mclass.c_name}")
-               self.ret(self.new_expr("NEW_{ret.mclass.c_name}({arguments[1]})", ret_type))
-       end
 end
index a9426c4..6d5ad40 100644 (file)
@@ -1177,8 +1177,6 @@ redef class AMethPropdef
                        else if pname == "utf8_length" then
                                return v.int_instance(args[0].val.as(NativeString).utf8_length(args[1].to_i, args[2].to_i))
                        end
-               else if pname == "calloc_string" then
-                       return v.native_string_instance_len(args[1].to_i)
                else if cname == "NativeArray" then
                        if pname == "new" then
                                var val = new Array[Instance].filled_with(v.null_instance, args[1].to_i)