Merge pull request #68 from ValKmjolnir/develop

⚡ use incremental garbage collector

CMakeLists.txt

@@ -39,6 +39,7 @@ set(NASAL_OBJECT_SOURCE_FILE
     ${CMAKE_SOURCE_DIR}/src/natives/unix_lib.cpp
     ${CMAKE_SOURCE_DIR}/src/repl/repl.cpp
     ${CMAKE_SOURCE_DIR}/src/util/fs.cpp
+    ${CMAKE_SOURCE_DIR}/src/util/gc_stat.cpp
     ${CMAKE_SOURCE_DIR}/src/util/util.cpp
     ${CMAKE_SOURCE_DIR}/src/ast_dumper.cpp
     ${CMAKE_SOURCE_DIR}/src/ast_format.cpp
@@ -97,6 +98,7 @@ set(CMAKE_LIBRARY_OUTPUT_DIRECTORY ${CMAKE_SOURCE_DIR}/module)
 
 set(MODULE_USED_OBJECT_SOURCE_FILE
     ${CMAKE_SOURCE_DIR}/src/util/util.cpp
+    ${CMAKE_SOURCE_DIR}/src/util/gc_stat.cpp
     ${CMAKE_SOURCE_DIR}/src/util/fs.cpp
     ${CMAKE_SOURCE_DIR}/src/nasal_type.cpp
     ${CMAKE_SOURCE_DIR}/src/nasal_gc.cpp)

src/cli/cli.cpp

@@ -105,7 +105,7 @@ std::ostream& logo(std::ostream& out) {
     << " - http://fgprc.org\n"
     << " - http://fgprc.org.cn\n"
     << "\n"
-    << "input <nasal-format -h> to get help.\n\n";
+    << "input <nasal -h> to get help.\n\n";
     return out;
 }
 

src/nasal_codegen.cpp

@@ -1436,6 +1436,7 @@ void codegen::print(std::ostream& out) {
     codestream::set(
         const_number_table.data(),
         const_string_table.data(),
+        global,
         native_function.data()
     );
 

src/nasal_dbg.cpp

@@ -163,7 +163,13 @@ void dbg::step_info() {
 
     begin = (ctx.pc>>3)==0? 0:((ctx.pc>>3)<<3);
     end = (1+(ctx.pc>>3))<<3;
-    codestream::set(const_number, const_string, native_function.data(), files);
+    codestream::set(
+        const_number,
+        const_string,
+        global_symbol_name,
+        native_function.data(),
+        files
+    );
 
     std::clog << "\nnext bytecode:\n";
     for(u64 i = begin; i<end && bytecode[i].op!=op_exit; ++i) {
@@ -290,7 +296,7 @@ void dbg::run(const codegen& gen,
             counter.dump_all_code_line_counter(std::clog):
             counter.dump_this_file_line_counter(std::clog);
     }
-    ngc.info();
+    ngc.status.dump_info();
     ngc.clear();
     imm.clear();
     return;

src/nasal_gc.cpp

@@ -1,33 +1,38 @@
 #include "nasal_gc.h"
-#include "util/util.h"
 
 namespace nasal {
 
 void gc::do_mark_sweep() {
-    using clk = std::chrono::high_resolution_clock;
+    count_mark_time();
-    auto begin = clk::now();
+    count_sweep_time();
-    mark();
+}
-    auto mark_end = clk::now();
-    sweep();
-    auto sweep_end = clk::now();
 
-    auto total_time = (sweep_end-begin).count();
+void gc::count_mark_time() {
-    auto mark_time = (mark_end-begin).count();
+    if (in_incremental_sweep_stage) {
-    auto sweep_time = (sweep_end-mark_end).count();
+        return;
-    worktime += total_time;
+    }
-    max_time = max_time<total_time? total_time:max_time;
+
-    max_mark_time = max_mark_time<mark_time? mark_time:max_mark_time;
+    status.stamp();
-    max_sweep_time = max_sweep_time<sweep_time? sweep_time:max_sweep_time;
+    mark();
+    status.elapsed_mark_time();
+
+    in_incremental_sweep_stage = true;
+    current_sweep_index = memory.size() - 1;
+}
+
+void gc::count_sweep_time() {
+    status.stamp();
+    sweep();
+    status.elapsed_sweep_time();
 }
 
 void gc::mark() {
     std::vector<var> bfs;
     mark_context_root(bfs);
 
-    // concurrent mark, experimental
+    // concurrent mark
-    if (memory.size()>UINT16_MAX && bfs.size()>32) {
+    if (memory.size() > UINT16_MAX * 16 && bfs.size() > 16) {
-        flag_concurrent_mark_triggered = true;
+        auto size = bfs.size();
-        usize size = bfs.size();
         std::thread t0(&gc::concurrent_mark, this, std::ref(bfs), 0, size/4);
         std::thread t1(&gc::concurrent_mark, this, std::ref(bfs), size/4, size/2);
         std::thread t2(&gc::concurrent_mark, this, std::ref(bfs), size/2, size/4*3);
@@ -179,20 +184,32 @@ void gc::mark_map(std::vector<var>& bfs_queue, nas_map& mp) {
 }
 
 void gc::sweep() {
-    for(auto i : memory) {
+    // if threshold is too small, too many allocated objects will be marked as "found"
+    // objects with "found" will be marked to "uncollected" in the next gc cycle
+    // this will cause memory wasting.
+    const i64 threshold = 4096;
+    for (i64 it = 0; it < threshold; ++it) {
+        if (current_sweep_index - it < 0) {
+            break;
+        }
+        auto i = memory[current_sweep_index - it];
         if (i->mark==nas_val::gc_status::uncollected) {
-            i->clear();
+            unused[static_cast<u32>(i->type)-static_cast<u32>(vm_type::vm_str)].push_back(i);
-            unused[static_cast<u8>(i->type)-static_cast<u8>(vm_type::vm_str)].push_back(i);
             i->mark = nas_val::gc_status::collected;
         } else if (i->mark==nas_val::gc_status::found) {
             i->mark = nas_val::gc_status::uncollected;
         }
     }
+    current_sweep_index -= threshold;
+    if (current_sweep_index < 0) {
+        in_incremental_sweep_stage = false;
+        current_sweep_index = 0;
+    }
 }
 
 void gc::extend(const vm_type type) {
-    const u8 index = static_cast<u8>(type)-static_cast<u8>(vm_type::vm_str);
+    const u32 index = static_cast<u32>(type)-static_cast<u32>(vm_type::vm_str);
-    size[index] += incr[index];
+    status.object_size[index] += incr[index];
 
     for(u64 i = 0; i<incr[index]; ++i) {
         // no need to check, will be killed if memory is not enough
@@ -204,35 +221,32 @@ void gc::extend(const vm_type type) {
     }
     switch(type) {
         case vm_type::vm_str:
-            total_memory_usage += incr[index] * sizeof(std::string); break;
+            total_object_count += incr[index] * sizeof(std::string); break;
         case vm_type::vm_vec:
-            total_memory_usage += incr[index] * sizeof(nas_vec); break;
+            total_object_count += incr[index] * sizeof(nas_vec); break;
         case vm_type::vm_hash:
-            total_memory_usage += incr[index] * sizeof(nas_hash); break;
+            total_object_count += incr[index] * sizeof(nas_hash); break;
         case vm_type::vm_func:
-            total_memory_usage += incr[index] * sizeof(nas_func); break;
+            total_object_count += incr[index] * sizeof(nas_func); break;
         case vm_type::vm_upval:
-            total_memory_usage += incr[index] * sizeof(nas_upval); break;
+            total_object_count += incr[index] * sizeof(nas_upval); break;
         case vm_type::vm_ghost:
-            total_memory_usage += incr[index] * sizeof(nas_ghost); break;
+            total_object_count += incr[index] * sizeof(nas_ghost); break;
         case vm_type::vm_co:
-            total_memory_usage += incr[index] * sizeof(nas_co); break;
+            total_object_count += incr[index] * sizeof(nas_co); break;
         case vm_type::vm_map:
-            total_memory_usage += incr[index] * sizeof(nas_map); break;
+            total_object_count += incr[index] * sizeof(nas_map); break;
         default: break;
     }
 
     // if incr[index] = 1, this will always be 1
-    incr[index] = incr[index] + incr[index]/2;
+    incr[index] = incr[index] + incr[index];
 }
 
 void gc::init(const std::vector<std::string>& constant_strings,
               const std::vector<std::string>& argv) {
-    // initialize counters
+    // initialize gc status recorder
-    worktime = 0;
+    status.init();
-    for(u8 i = 0; i<gc_type_size; ++i) {
-        size[i] = gcnt[i] = acnt[i] = 0;
-    }
 
     // coroutine pointer set to nullptr
     cort = nullptr;
@@ -247,8 +261,8 @@ void gc::init(const std::vector<std::string>& constant_strings,
         strs[i] = var::gcobj(new nas_val(vm_type::vm_str));
         strs[i].val.gcobj->immutable = 1;
         strs[i].str() = constant_strings[i];
-        total_memory_usage += strs[i].str().size();
+        total_object_count += strs[i].str().size();
-        total_memory_usage += sizeof(std::string);
+        total_object_count += sizeof(std::string);
     }
 
     // record arguments
@@ -261,8 +275,8 @@ void gc::init(const std::vector<std::string>& constant_strings,
         env_argv[i] = var::gcobj(new nas_val(vm_type::vm_str));
         env_argv[i].val.gcobj->immutable = 1;
         env_argv[i].str() = argv[i];
-        total_memory_usage += env_argv[i].str().size();
+        total_object_count += env_argv[i].str().size();
-        total_memory_usage += sizeof(std::string);
+        total_object_count += sizeof(std::string);
     }
 }
 
@@ -271,7 +285,7 @@ void gc::clear() {
         delete i;
     }
     memory.clear();
-    for(u8 i = 0; i<gc_type_size; ++i) {
+    for(u32 i = 0; i<GC_TYPE_SIZE; ++i) {
         unused[i].clear();
     }
     for(auto& i : strs) {
@@ -281,158 +295,35 @@ void gc::clear() {
     env_argv.clear();
 }
 
-void gc::info() const {
-    util::windows_code_page_manager wm;
-    wm.set_utf8_output();
-
-    using std::left;
-    using std::setw;
-    using std::setfill;
-    using std::setprecision;
-
-    const char* used_table_name[] = {
-        "object type",
-        "gc count",
-        "alloc count",
-        "memory size",
-        "detail",
-        "time spend",
-        "gc time",
-        "avg time",
-        "max gc",
-        "max mark",
-        "max sweep",
-        nullptr
-    };
-    const char* name[] = {
-        "string",
-        "vector",
-        "hashmap",
-        "function",
-        "upvalue",
-        "ghost",
-        "coroutine",
-        "namespace",
-        nullptr
-    };
-
-    usize indent = 0, len = 0;
-    for(usize i = 0; used_table_name[i]; ++i) {
-        len = std::string(used_table_name[i]).length();
-        indent = indent<len? len:indent;
-    }
-    for(usize i = 0; name[i]; ++i) {
-        len = std::string(name[i]).length();
-        indent = indent<len? len:indent;
-    }
-    for(u32 i = 0; i<gc_type_size; ++i) {
-        len = std::to_string(gcnt[i]).length();
-        indent = indent<len? len:indent;
-        len = std::to_string(acnt[i]).length();
-        indent = indent<len? len:indent;
-        len = std::to_string(size[i]).length();
-        indent = indent<len? len:indent;
-    }
-    auto indent_string = std::string("──");
-    for(usize i = 0; i<indent; ++i) {
-        indent_string += "─";
-    }
-    const auto first_line = "╭" + indent_string + "┬" +
-                            indent_string + "┬" +
-                            indent_string + "┬" +
-                            indent_string + "╮";
-    const auto second_line = "├" + indent_string + "┼" +
-                             indent_string + "┼" +
-                             indent_string + "┼" +
-                             indent_string + "┤";
-    const auto mid_line = "├" + indent_string + "┼" +
-                          indent_string + "┴" +
-                          indent_string + "┴" +
-                          indent_string + "┤";
-    const auto another_mid_line = "├" + indent_string + "┼" +
-                                  indent_string + "─" +
-                                  indent_string + "─" +
-                                  indent_string + "┤";
-    const auto last_line = "╰" + indent_string + "┴" +
-                           indent_string + "─" +
-                           indent_string + "─" +
-                           indent_string + "╯";
-
-    std::clog << "\n" << first_line << "\n";
-    std::clog << "│ " << left << setw(indent) << setfill(' ') << "object type";
-    std::clog << " │ " << left << setw(indent) << setfill(' ') << "gc count";
-    std::clog << " │ " << left << setw(indent) << setfill(' ') << "alloc count";
-    std::clog << " │ " << left << setw(indent) << setfill(' ') << "memory size";
-    std::clog << " │\n" << second_line << "\n";
-
-    double total = 0;
-    for(u8 i = 0; i<gc_type_size; ++i) {
-        if (!gcnt[i] && !acnt[i] && !size[i]) {
-            continue;
-        }
-        total += static_cast<f64>(gcnt[i]);
-        std::clog << "│ " << left << setw(indent) << setfill(' ') << name[i];
-        std::clog << " │ " << left << setw(indent) << setfill(' ') << gcnt[i];
-        std::clog << " │ " << left << setw(indent) << setfill(' ') << acnt[i];
-        std::clog << " │ " << left << setw(indent) << setfill(' ') << size[i];
-        std::clog << " │\n";
-    }
-    std::clog << mid_line << "\n";
-
-    const auto den = std::chrono::high_resolution_clock::duration::period::den;
-    std::clog << "│ " << left << setw(indent) << setfill(' ') << "detail";
-    std::clog << " │ " << left << setw(indent) << setfill(' ') << "time spend";
-    std::clog << "   " << left << setw(indent) << setfill(' ') << " ";
-    std::clog << "   " << left << setw(indent) << setfill(' ') << " ";
-    std::clog << " │\n" << another_mid_line << "\n";
-
-    const auto gc_time = worktime*1.0/den*1000;
-    std::clog << "│ " << left << setw(indent) << setfill(' ') << "gc time";
-    std::clog << " │ " << setw(indent-3) << setprecision(4) << gc_time << " ms";
-    std::clog << setw(indent*2+7) << " " << "│\n";
-
-    const auto avg_time = worktime*1.0/den*1000/total;
-    std::clog << "│ " << left << setw(indent) << setfill(' ') << "avg time";
-    std::clog << " │ " << setw(indent-3) << setprecision(4) << avg_time << " ms";
-    std::clog << setw(indent*2+7) << " " << "│\n";
-
-    const auto max_gc = max_time*1.0/den*1000;
-    std::clog << "│ " << left << setw(indent) << setfill(' ') << "max gc";
-    std::clog << " │ " << setw(indent-3) << setprecision(4) << max_gc << " ms";
-    std::clog << setw(indent*2+7) << " " << "│\n";
-
-    const auto max_mark = max_mark_time*1.0/den*1000;
-    std::clog << "│ " << left << setw(indent) << setfill(' ') << "max mark";
-    std::clog << " │ " << setw(indent-3) << setprecision(4) << max_mark << " ms";
-    std::clog << setw(indent*2+7) << " " << "│\n";
-
-    const auto max_sweep = max_sweep_time*1.0/den*1000;
-    std::clog << "│ " << left << setw(indent) << setfill(' ') << "max sweep";
-    std::clog << " │ " << setw(indent-3) << setprecision(4) << max_sweep << " ms";
-    std::clog << setw(indent*2+7) << " " << "│\n";
-
-    std::clog << "│ " << left << setw(indent) << setfill(' ') << "concurrent";
-    std::clog << " │ " << setw(indent)
-              << (flag_concurrent_mark_triggered? "true":"false");
-    std::clog << setw(indent*2+7) << " " << "│\n";
-
-    std::clog << last_line << "\n";
-
-    wm.restore_code_page();
-}
-
 var gc::alloc(const vm_type type) {
-    const u8 index = static_cast<u8>(type)-static_cast<u8>(vm_type::vm_str);
+    const u32 index = static_cast<u32>(type)-static_cast<u32>(vm_type::vm_str);
-    ++acnt[index];
+    ++status.alloc_count[index];
-    if (unused[index].empty()) {
+    // if still in incremental sweep stage? do it
-        ++gcnt[index];
+    // if not in incremental sweep stage, run a new gc cycle
+    if (in_incremental_sweep_stage) {
+        do_mark_sweep();
+    } else if (unused[index].empty()) {
+        ++status.gc_cycle_trigger_count[index];
         do_mark_sweep();
     }
+    // if in incremental sweep stage, but the unused list is empty,
+    // do it until the unused list has something
+    while (unused[index].empty() && in_incremental_sweep_stage) {
+        do_mark_sweep();
+    }
+    // after all gc stages, still get empty list, extend
     if (unused[index].empty()) {
         extend(type);
     }
+
     var ret = var::gcobj(unused[index].back());
-    ret.val.gcobj->mark = nas_val::gc_status::uncollected;
+    ret.val.gcobj->clear();
+
+    // if incremental sweep stage, mark it as found
+    // but be aware that it may be collected in next gc cycle
+    ret.val.gcobj->mark = in_incremental_sweep_stage
+        ? nas_val::gc_status::found
+        : nas_val::gc_status::uncollected;
     unused[index].pop_back();
     return ret;
 }
@@ -453,9 +344,9 @@ void gc::context_change(nas_co* co) {
 
 void gc::context_reserve() {
     // pc = 0 means this coroutine is finished
-    cort->status = running_context->pc?
+    cort->status = running_context->pc
-        nas_co::status::suspended:
+        ? nas_co::status::suspended
-        nas_co::status::dead;
+        : nas_co::status::dead;
 
     // store running state to coroutine
     cort->ctx = *running_context;

src/nasal_gc.h

@@ -17,9 +17,18 @@
 
 #include "nasal.h"
 #include "nasal_type.h"
+#include "util/gc_stat.h"
 
 namespace nasal {
 
+struct free_list {
+    std::vector<nas_val*> elem[GC_TYPE_SIZE];
+
+    auto& operator[](i64 index) {
+        return elem[index];
+    }
+};
+
 struct gc {
     /* main context temporary storage */
     context main_context;
@@ -39,31 +48,28 @@ struct gc {
     std::vector<var> strs = {};     // reserved address for const vm_str
     std::vector<var> env_argv = {}; // command line arguments
     std::vector<nas_val*> memory;   // gc memory
-    std::vector<nas_val*> unused[gc_type_size]; // gc free list
+    free_list unused;               // gc free list
 
     /* heap increase size */
-    u64 incr[gc_type_size] = {
+    u64 incr[GC_TYPE_SIZE] = {
-        128, // vm_str
+        256, // vm_str
-        128, // vm_vec
+        256, // vm_vec
-        64,  // vm_hash
+        256, // vm_hash
         256, // vm_func
         256, // vm_upval
-        16,  // vm_obj
+        4,   // vm_obj
-        16,  // vm_co
+        4,   // vm_co
-        2,   // vm_map
+        1,   // vm_map
     };
-    // total memory usage, not very accurate
+
-    u64 total_memory_usage = 0;
+    // total object count
+    u64 total_object_count = 0;
 
     /* values for analysis */
-    u64 size[gc_type_size];
+    gc_stat status;
-    u64 gcnt[gc_type_size];
+
-    u64 acnt[gc_type_size];
+    bool in_incremental_sweep_stage = false;
-    i64 worktime = 0;
+    i64 current_sweep_index = 0;
-    i64 max_time = 0;
-    i64 max_mark_time = 0;
-    i64 max_sweep_time = 0;
-    bool flag_concurrent_mark_triggered = false;
 
     void set(context* _ctx, var* _global, usize _size) {
         running_context = _ctx;
@@ -74,6 +80,8 @@ struct gc {
 private:
     /* gc functions */
     void do_mark_sweep();
+    void count_mark_time();
+    void count_sweep_time();
     void mark();
     void concurrent_mark(std::vector<var>&, usize, usize);
     void mark_context_root(std::vector<var>&);
@@ -91,19 +99,18 @@ public:
     void extend(const vm_type);
     void init(const std::vector<std::string>&, const std::vector<std::string>&);
     void clear();
-    void info() const;
     var alloc(const vm_type);
     void context_change(nas_co*);
     void context_reserve();
 
 public:
-    double get_gc_time_ms() const {
+    f64 get_gc_time_ms() const {
-        const auto den = std::chrono::high_resolution_clock::duration::period::den;
+        return status.gc_time_ms();
-        return worktime * 1.0 / den * 1000.0;
     }
 
-    double get_total_memory() const {
+    // not very accurate
-        return total_memory_usage * 1.0 / 1024.0 / 1024.0;
+    f64 get_total_memory() const {
+        return total_object_count * 3.5 / 1024.0 / 1024.0;
     }
 
 public:

src/nasal_opcode.cpp

@@ -5,12 +5,31 @@ namespace nasal {
 
 void codestream::set(const f64* number_list,
                      const std::string* string_list,
+                     const std::unordered_map<std::string, u64>& globals,
                      const nasal_builtin_table* native_table,
                      const std::string* file_list) {
     const_number = number_list;
     const_string = string_list;
     natives = native_table;
     files = file_list;
+
+    global_variable.resize(globals.size());
+    for(auto& [name, index]: globals) {
+        global_variable[index] = name;
+    }
+}
+
+void codestream::set(const f64* number_list,
+                     const std::string* string_list,
+                     const std::vector<std::string>& globals,
+                     const nasal_builtin_table* native_table,
+                     const std::string* file_list) {
+    const_number = number_list;
+    const_string = string_list;
+    natives = native_table;
+    files = file_list;
+
+    global_variable = globals;
 }
 
 void codestream::dump(std::ostream& out) const {
@@ -93,13 +112,16 @@ void codestream::dump(std::ostream& out) const {
         case op_jmp:
         case op_jt:
         case op_jf:
-        case op_callg:
-        case op_mcallg:
         case op_loadg:
         case op_calll:
         case op_mcalll:
         case op_loadl:
             out << hex << "0x" << num << dec; break;
+        case op_mcallg:
+        case op_callg:
+            out << hex << "0x" << num << dec;
+            out << " (" << util::rawstr(global_variable[num], 32) << ")";
+            break;
         case op_callb:
             out << hex << "0x" << num << dec;
             out << " <" << natives[num].name << "@0x";

src/nasal_opcode.h

@@ -4,6 +4,10 @@
 #include "natives/builtin.h"
 
 #include <iostream>
+#include <vector>
+#include <cstring>
+#include <sstream>
+#include <unordered_map>
 
 namespace nasal {
 
@@ -207,16 +211,22 @@ private:
     inline static const std::string* const_string = nullptr;
     inline static const nasal_builtin_table* natives = nullptr;
     inline static const std::string* files = nullptr;
+    inline static std::vector<std::string> global_variable;
     
 public:
     codestream(const opcode& c, const u64 i): code(c), index(i) {}
     static void set(const f64*,
                     const std::string*,
+                    const std::unordered_map<std::string, u64>&,
+                    const nasal_builtin_table*,
+                    const std::string* file_list = nullptr);
+    static void set(const f64*,
+                    const std::string*,
+                    const std::vector<std::string>&,
                     const nasal_builtin_table*,
                     const std::string* file_list = nullptr);
     void dump(std::ostream&) const;
+    friend std::ostream& operator<<(std::ostream&, const codestream&);
 };
 
-std::ostream& operator<<(std::ostream&, const codestream&);
-
 }

src/nasal_type.h

@@ -35,7 +35,7 @@ enum class vm_type: u8 {
 };
 
 // size of gc object type
-const u32 gc_type_size =
+const u32 GC_TYPE_SIZE =
     static_cast<u32>(vm_type::vm_type_size_max) -
     static_cast<u32>(vm_type::vm_str);
 

src/nasal_vm.cpp

@@ -225,12 +225,24 @@ void vm::function_call_trace() {
     std::stack<const nas_func*> functions;
     std::stack<u64> callsite;
 
-    // load call trace
+    // load call trace, from bottom to top
     for(var* i = bottom; i <= top; ++i) {
         // i-1 is the callsite program counter of this function
-        if (i->is_addr() && i+2<=top &&
+        //   +-------+----------------+
-            (i+1)->is_ret() && (i+1)->ret()>0 &&
+        //   | func  | func() {..}    | <-- i + 2
-            (i+2)->is_func()) {
+        //   +-------+----------------+
+        //   | ret   | 0x3bf          | <-- i + 1 (value should not be 0x0)
+        //   +-------+----------------+
+        //   | addr  | 0x7ff5f61ae020 | <-- i
+        //   +-------+----------------+
+        // TODO: op_cnt may destroy the order, so maybe this need refact
+        if (i + 2 > top) {
+            continue;
+        }
+        if (!i->is_addr()) {
+            continue;
+        }
+        if ((i+1)->is_ret() && (i+1)->ret()>0 && (i+2)->is_func()) {
             functions.push(&(i+2)->func());
             callsite.push((i+1)->ret());
         }
@@ -239,10 +251,18 @@ void vm::function_call_trace() {
     // another condition may exist
     // have ret pc on stack, but no function at the top of the ret pc
     for(var * i = top; i >= bottom; --i) {
+        //   +-------+----------------+
+        //   | xxxx  | xxxx           | <-- i + 2 (not function or not exist)
+        //   +-------+----------------+
+        //   | ret   | 0x3bf          | <-- i + 1 (value should not be 0x0)
+        //   +-------+----------------+
+        //   | addr  | 0x7ff5f61ae020 | <-- i
+        //   +-------+----------------+
         if ((i->is_addr() && i+2<=top && (i+1)->is_ret() && !(i+2)->is_func()) ||
             (i->is_addr() && i+1<=top && i+2>top && (i+1)->is_ret())) {
             functions.push(&ctx.funcr.func());
             callsite.push((i+1)->ret());
+            break;
         }
     }
 
@@ -307,7 +327,13 @@ void vm::trace_back() {
 
     std::clog << "\nback trace ";
     std::clog << (ngc.cort? "(coroutine)":"(main)") << "\n";
-    codestream::set(const_number, const_string, native_function.data(), files);
+    codestream::set(
+        const_number,
+        const_string,
+        global_symbol_name,
+        native_function.data(),
+        files
+    );
 
     for(u64 p = 0, same = 0, prev = 0xffffffff; !ret.empty(); prev = p, ret.pop()) {
         if ((p = ret.top())==prev) {
@@ -370,7 +396,7 @@ void vm::global_state() {
               << reinterpret_cast<u64>(global) << ")\n" << std::dec;
     for(usize i = 0; i<global_size; ++i) {
         std::clog << "  0x" << std::hex << std::setw(8)
-                  << std::setfill('0') << i << std::dec
+                  << std::setfill('0') << static_cast<u64>(i) << std::dec
                   << "    ";
         auto name = global_symbol_name[i];
         if (name.length()>=10) {
@@ -379,7 +405,8 @@ void vm::global_state() {
 
         }
         std::clog << "| " << std::left << std::setw(10)
-                  << std::setfill(' ') << name << " ";
+                  << std::setfill(' ') << name << " "
+                  << std::internal;
         value_info(global[i]);
     }
 }
@@ -696,7 +723,7 @@ void vm::run(const codegen& gen,
 // all nasal programs should end here
 vmexit:
     if (verbose) {
-        ngc.info();
+        ngc.status.dump_info();
     }
     imm.clear();
     if (!is_repl_mode) {

src/natives/builtin.cpp

@@ -381,7 +381,10 @@ var builtin_substr(context* ctx, gc* ngc) {
     auto begin = static_cast<usize>(beg.num());
     auto length = static_cast<usize>(len.num());
     if (begin >= str.str().length()) {
-        return nas_err("native::susbtr", "begin index out of range: "+std::to_string(begin));
+        return nas_err(
+            "native::susbtr",
+            "begin index out of range: " + std::to_string(begin)
+        );
     }
     return ngc->newstr(str.str().substr(begin, length));
 }
@@ -720,27 +723,17 @@ var builtin_gcextend(context* ctx, gc* ngc) {
 }
 
 var builtin_gcinfo(context* ctx, gc* ngc) {
-    const auto den = std::chrono::high_resolution_clock::duration::period::den;
     var res = ngc->alloc(vm_type::vm_hash);
-
-    f64 total = 0;
-    for(u32 i = 0; i<gc_type_size; ++i) {
-        total += static_cast<f64>(ngc->gcnt[i]);
-    }
-
-
     auto& map = res.hash().elems;
-    const auto worktime = static_cast<f64>(ngc->worktime);
-    const auto max_time = static_cast<f64>(ngc->max_time);
-    const auto max_mark_time = static_cast<f64>(ngc->max_mark_time);
-    const auto max_sweep_time = static_cast<f64>(ngc->max_sweep_time);
-
     // using ms
-    map["total"] = var::num(worktime/den*1000);
+    map["total"] = var::num(ngc->status.gc_time_ms());
-    map["average"] = var::num(worktime/den*1000/total);
+    map["average"] = var::num(ngc->status.avg_time_ms());
-    map["max_gc"] = var::num(max_time/den*1000);
+    map["mark_count"] = var::num(ngc->status.total_mark_count);
-    map["max_mark"] = var::num(max_mark_time/den*1000);
+    map["sweep_count"] = var::num(ngc->status.total_sweep_count);
-    map["max_sweep"] = var::num(max_sweep_time/den*1000);
+    map["avg_mark"] = var::num(ngc->status.avg_mark_time_ms());
+    map["avg_sweep"] = var::num(ngc->status.avg_sweep_time_ms());
+    map["max_mark"] = var::num(ngc->status.max_mark_time_ms());
+    map["max_sweep"] = var::num(ngc->status.max_sweep_time_ms());
     return res;
 }
 

src/natives/io_lib.cpp

@@ -59,8 +59,9 @@ var builtin_open(context* ctx, gc* ngc) {
         return nas_err("io::open", "\"mode\" must be string");
     }
     auto file_descriptor = fopen(name.str().c_str(), mode.str().c_str());
+    // if failed to open, just return nil for check
     if (!file_descriptor) {
-        return nas_err("io::open", "failed to open file <" + name.str() + ">");
+        return nil;
     }
     var return_object = ngc->alloc(vm_type::vm_ghost);
     return_object.ghost().set(

src/natives/regex_lib.cpp

@@ -2,7 +2,7 @@
 
 namespace nasal {
 
-var builtin_regex_match(context* ctx, gc* ngc) {
+var builtin_regex_match(context* ctx, gc* ngc) noexcept {
     auto source = ctx->localr[1];
     auto reg_str = ctx->localr[2];
     if (!source.is_str()) {
@@ -20,7 +20,7 @@ var builtin_regex_match(context* ctx, gc* ngc) {
     return zero;
 }
 
-var builtin_regex_search(context* ctx, gc* ngc) {
+var builtin_regex_search(context* ctx, gc* ngc) noexcept {
     auto source = ctx->localr[1];
     auto reg_str = ctx->localr[2];
     if (!source.is_str()) {
@@ -38,7 +38,7 @@ var builtin_regex_search(context* ctx, gc* ngc) {
     return nil;
 }
 
-var builtin_regex_replace(context* ctx, gc* ngc) {
+var builtin_regex_replace(context* ctx, gc* ngc) noexcept {
     auto source = ctx->localr[1];
     auto reg_str = ctx->localr[2];
     auto fmt = ctx->localr[3];
@@ -64,7 +64,7 @@ var builtin_regex_replace(context* ctx, gc* ngc) {
     return ngc->newstr(source.str());
 }
 
-var builtin_regex_match_all(context* ctx, gc* ngc) {
+var builtin_regex_match_all(context* ctx, gc* ngc) noexcept {
     auto source = ctx->localr[1];
     auto reg_str = ctx->localr[2];
     if (!source.is_str()) {

src/natives/regex_lib.h

@@ -8,10 +8,10 @@
 
 namespace nasal {
 
-var builtin_regex_match(context*, gc*);
+var builtin_regex_match(context*, gc*) noexcept;
-var builtin_regex_search(context*, gc*);
+var builtin_regex_search(context*, gc*) noexcept;
-var builtin_regex_replace(context*, gc*);
+var builtin_regex_replace(context*, gc*) noexcept;
-var builtin_regex_match_all(context*, gc*);
+var builtin_regex_match_all(context*, gc*) noexcept;
 
 extern nasal_builtin_table regex_lib_native[];
 

src/util/gc_stat.cpp

@@ -0,0 +1,193 @@
+#include "util/util.h"
+#include "util/gc_stat.h"
+
+#include <chrono>
+#include <iomanip>
+
+namespace nasal {
+
+void gc_stat::init() {
+    for (i64 i = 0; i < GC_TYPE_SIZE; i++) {
+        object_size[i] = 0;
+        alloc_count[i] = 0;
+        gc_cycle_trigger_count[i] = 0;
+    }
+
+    total_mark_count = 0;
+    total_sweep_count = 0;
+
+    total_mark_time = 0;
+    total_sweep_time = 0;
+
+    max_mark_time = 0;
+    max_sweep_time = 0;
+}
+
+f64 gc_stat::gc_time_ms() const {
+    const auto den = std::chrono::high_resolution_clock::duration::period::den;
+    return ((total_mark_time + total_sweep_time) * 1000.0) / den;
+}
+
+f64 gc_stat::avg_time_ms() const {
+    u64 total_gc_cycle = 0;
+    for (i64 i = 0; i < GC_TYPE_SIZE; i++) {
+        total_gc_cycle += gc_cycle_trigger_count[i];
+    }
+    return gc_time_ms() / total_mark_count;
+}
+
+f64 gc_stat::avg_mark_time_ms() const {
+    const auto den = std::chrono::high_resolution_clock::duration::period::den;
+    return (total_mark_time * 1000.0) / den / total_mark_count;
+}
+
+f64 gc_stat::avg_sweep_time_ms() const {
+    const auto den = std::chrono::high_resolution_clock::duration::period::den;
+    return (total_sweep_time * 1000.0) / den / total_sweep_count;
+}
+
+f64 gc_stat::max_mark_time_ms() const {
+    const auto den = std::chrono::high_resolution_clock::duration::period::den;
+    return (max_mark_time * 1000.0) / den;
+}
+
+f64 gc_stat::max_sweep_time_ms() const {
+    const auto den = std::chrono::high_resolution_clock::duration::period::den;
+    return (max_sweep_time * 1000.0) / den;
+}
+
+void gc_stat::dump_info() const {
+    util::windows_code_page_manager wm;
+    wm.set_utf8_output();
+
+    using std::left;
+    using std::setw;
+    using std::setfill;
+    using std::setprecision;
+
+    const char* used_table_name[] = {
+        "object type",
+        "gc cycle",
+        "alloc count",
+        "object count",
+        "detail",
+        "time spend",
+        "gc time",
+        "avg time",
+        "max gc",
+        "max mark",
+        "max sweep"
+    };
+    const char* name[] = {
+        "string",
+        "vector",
+        "hashmap",
+        "function",
+        "upvalue",
+        "ghost",
+        "coroutine",
+        "namespace"
+    };
+
+    // calculate max indent length
+    usize indent = 0;
+    for (auto tname : used_table_name) {
+        auto len = strlen(tname);
+        indent = indent<len? len:indent;
+    }
+    for (auto n : name) {
+        auto len = strlen(n);
+        indent = indent<len? len:indent;
+    }
+    for(u32 i = 0; i < GC_TYPE_SIZE; ++i) {
+        auto len = std::to_string(gc_cycle_trigger_count[i]).length();
+        indent = indent<len? len:indent;
+        len = std::to_string(alloc_count[i]).length();
+        indent = indent<len? len:indent;
+        len = std::to_string(object_size[i]).length();
+        indent = indent<len? len:indent;
+    }
+
+    auto indent_string = std::string("──");
+    for(usize i = 0; i < indent; ++i) {
+        indent_string += "─";
+    }
+
+    const auto first_line = "╭" + indent_string + "┬" +
+                            indent_string + "┬" +
+                            indent_string + "┬" +
+                            indent_string + "╮";
+    const auto second_line = "├" + indent_string + "┼" +
+                             indent_string + "┼" +
+                             indent_string + "┼" +
+                             indent_string + "┤";
+    const auto mid_line = "├" + indent_string + "┼" +
+                          indent_string + "┴" +
+                          indent_string + "┴" +
+                          indent_string + "┤";
+    const auto another_mid_line = "├" + indent_string + "┼" +
+                                  indent_string + "─" +
+                                  indent_string + "─" +
+                                  indent_string + "┤";
+    const auto last_line = "╰" + indent_string + "┴" +
+                           indent_string + "─" +
+                           indent_string + "─" +
+                           indent_string + "╯";
+
+    std::clog << "\n" << first_line << "\n";
+    std::clog << "│ " << left << setw(indent) << setfill(' ') << "object type";
+    std::clog << " │ " << left << setw(indent) << setfill(' ') << "gc cycle";
+    std::clog << " │ " << left << setw(indent) << setfill(' ') << "alloc count";
+    std::clog << " │ " << left << setw(indent) << setfill(' ') << "object count";
+    std::clog << " │\n" << second_line << "\n" << std::internal;
+
+    for (u32 i = 0; i < GC_TYPE_SIZE; ++i) {
+        if (!gc_cycle_trigger_count[i] &&
+            !alloc_count[i] &&
+            !object_size[i]) {
+            continue;
+        }
+        std::clog << "│ " << left << setw(indent) << setfill(' ') << name[i];
+        std::clog << " │ " << left << setw(indent) << setfill(' ') << gc_cycle_trigger_count[i];
+        std::clog << " │ " << left << setw(indent) << setfill(' ') << alloc_count[i];
+        std::clog << " │ " << left << setw(indent) << setfill(' ') << object_size[i];
+        std::clog << " │\n" << std::internal;
+    }
+    std::clog << mid_line << "\n";
+
+    std::clog << "│ " << left << setw(indent) << setfill(' ') << "detail";
+    std::clog << " │ " << left << setw(indent) << setfill(' ') << "time spend";
+    std::clog << "   " << left << setw(indent) << setfill(' ') << " ";
+    std::clog << "   " << left << setw(indent) << setfill(' ') << " ";
+    std::clog << " │\n" << another_mid_line << "\n";
+
+    std::clog << "│ " << left << setw(indent) << setfill(' ') << "gc time";
+    std::clog << " │ " << setw(indent-3) << setprecision(4) << gc_time_ms() << " ms";
+    std::clog << setw(indent*2+7) << " " << "│\n";
+
+    std::clog << "│ " << left << setw(indent) << setfill(' ') << "avg time";
+    std::clog << " │ " << setw(indent-3) << setprecision(4) << avg_time_ms() << " ms";
+    std::clog << setw(indent*2+7) << " " << "│\n";
+
+    std::clog << "│ " << left << setw(indent) << setfill(' ') << "avg mark";
+    std::clog << " │ " << setw(indent-3) << setprecision(4) << avg_mark_time_ms() << " ms";
+    std::clog << setw(indent*2+7) << " " << "│\n";
+
+    std::clog << "│ " << left << setw(indent) << setfill(' ') << "avg sweep";
+    std::clog << " │ " << setw(indent-3) << setprecision(4) << avg_sweep_time_ms() << " ms";
+    std::clog << setw(indent*2+7) << " " << "│\n";
+
+    std::clog << "│ " << left << setw(indent) << setfill(' ') << "max mark";
+    std::clog << " │ " << setw(indent-3) << setprecision(4) << max_mark_time_ms() << " ms";
+    std::clog << setw(indent*2+7) << " " << "│\n";
+
+    std::clog << "│ " << left << setw(indent) << setfill(' ') << "max sweep";
+    std::clog << " │ " << setw(indent-3) << setprecision(4) << max_sweep_time_ms() << " ms";
+    std::clog << setw(indent*2+7) << " " << "│\n";
+
+    std::clog << last_line << "\n" << std::internal;
+
+    wm.restore_code_page();
+}
+
+}

src/util/gc_stat.h

@@ -0,0 +1,57 @@
+#pragma once
+
+#include "nasal.h"
+#include "nasal_type.h"
+
+#include <chrono>
+
+namespace nasal {
+
+struct gc_stat {
+    u64 object_size[GC_TYPE_SIZE];
+    u64 gc_cycle_trigger_count[GC_TYPE_SIZE];
+    u64 alloc_count[GC_TYPE_SIZE];
+
+    u64 total_mark_count = 0;
+    u64 total_sweep_count = 0;
+
+    i64 total_mark_time = 0;
+    i64 total_sweep_time = 0;
+
+    i64 max_mark_time = 0;
+    i64 max_sweep_time = 0;
+
+    std::chrono::time_point<std::chrono::high_resolution_clock> start_time;
+
+    void stamp() {
+        start_time = std::chrono::high_resolution_clock::now();
+    }
+
+    void elapsed_mark_time() {
+        auto end = std::chrono::high_resolution_clock::now();
+        auto mark_time = (end - start_time).count();
+        ++total_mark_count;
+        total_mark_time += mark_time;
+        max_mark_time = max_mark_time > mark_time ? max_mark_time : mark_time;
+    }
+
+    void elapsed_sweep_time() {
+        auto end = std::chrono::high_resolution_clock::now();
+        auto sweep_time = (end - start_time).count();
+        ++total_sweep_count;
+        total_sweep_time += sweep_time;
+        max_sweep_time = max_sweep_time > sweep_time ? max_sweep_time : sweep_time;
+    }
+
+    void init();
+    f64 gc_time_ms() const;
+    f64 avg_time_ms() const;
+    f64 avg_mark_time_ms() const;
+    f64 avg_sweep_time_ms() const;
+    f64 max_mark_time_ms() const;
+    f64 max_sweep_time_ms() const;
+
+    void dump_info() const;
+};
+
+}

test/gc_test.nas

@@ -6,51 +6,53 @@ var test_func = func(test_processes...) {
     test_process_total.stamp();
 
     var time_stamp = maketimestamp();
-    var info = runtime.gc.info();
+    var begin_info = runtime.gc.info();
-    var gc_total = info.total;
+    var gc_total_begin = begin_info.total;
-    var duration = 0;
+
     foreach (var f; test_processes) {
-        println("[", os.time(), "] testing ", id(f));
-        time_stamp.stamp();
         f();
-        duration = time_stamp.elapsedMSec();
+        print(".");
-        info = runtime.gc.info();
-        println("[", os.time(), "] ", duration, " ms, gc ",
-            (info.total-gc_total)*100/duration, "%, ",
-            1000/duration, " cps");
-        gc_total = info.total;
     }
 
-    println("[", os.time(), "] test time: ",
+    var end_info = runtime.gc.info();
-        test_process_total.elapsedMSec(), " ms");
+    var gc_total_end = end_info.total;
+    var duration = time_stamp.elapsedMSec();
+    println(" ", duration, " ms,\tgc ",
+        int((gc_total_end-gc_total_begin)*100/duration), "%,\t",
+        int(1000/(duration/size(test_processes))*10)/10, " test(s)/sec"
+    );
 
-    info = runtime.gc.info();
+    var info = runtime.gc.info();
-    println("##-gc----------------");
+    println("+##-gc----------------------");
-    println("total    : ", info.total, " ms");
+    println("| avg gc cycle : ", int(1000 / info.average), " exec/sec");
-    println("average  : ", info.average, " ms");
+    println("| avg mark     : ", int(1000 / info.avg_mark), " exec/sec");
-    println("max gc   : ", info.max_gc, " ms");
+    println("| avg sweep    : ", int(1000 / info.avg_sweep), " exec/sec");
-    println("max mark : ", info.max_mark, " ms");
+    println("| mark count   : ", info.mark_count);
-    println("max sweep: ", info.max_sweep, " ms");
+    println("| sweep count  : ", info.sweep_count);
-    println("---------------------");
+    println("| max mark     : ", info.max_mark, " ms");
+    println("| max sweep    : ", info.max_sweep, " ms");
+    println("+---------------------------");
 }
 
+var MAX_ITER_NUM = 0.5e5;
+
 var append_vec = func {
     var res = [];
-    for(var i=0; i<1e6; i+=1) {
+    for(var i=0; i<MAX_ITER_NUM; i+=1) {
-        append(res, [1]);
+        append(res, [1, 2, 3, 4]);
     }
 }
 
 var append_hash = func {
     var res = [];
-    for(var i=0; i<1e6; i+=1) {
+    for(var i=0; i<MAX_ITER_NUM; i+=1) {
-        append(res, {a:1, b:2});
+        append(res, {a:1, b:2, c:3, d:4});
     }
 }
 
 var append_func = func {
     var res = [];
-    for(var i=0; i<1e6; i+=1) {
+    for(var i=0; i<MAX_ITER_NUM; i+=1) {
         append(res, func {
             println(arg);
         });
@@ -59,14 +61,47 @@ var append_func = func {
 
 var append_vec_in_vec = func {
     var res = [];
-    for(var i=0; i<1e6; i+=1) {
+    for(var i=0; i<MAX_ITER_NUM; i+=1) {
-        append(res, [[]]);
+        append(res, [[], [], [], []]);
+    }
+}
+
+var append_hash_in_vec = func {
+    var res = [];
+    for(var i=0; i<MAX_ITER_NUM; i+=1) {
+        append(res, [{}, {}, {}, {}]);
     }
 }
 
 var append_vec_in_hash = func {
-    for(var i=0; i<1e6; i+=1) {
+    var res = [];
-        append([], {a:[], b:[]});
+    for(var i=0; i<MAX_ITER_NUM; i+=1) {
+        append(res, {a:[], b:[], c:[], d:[]});
+    }
+}
+
+var append_hash_in_hash = func {
+    var res = [];
+    for(var i=0; i<MAX_ITER_NUM; i+=1) {
+        append(res, {a:{}, b:{}, c:{}, d:{}});
+    }
+}
+
+var append_hash_vec_hash = func {
+    var res = [];
+    for(var i=0; i<MAX_ITER_NUM; i+=1) {
+        append(res, {a:[{}], b:[{}], c:[{}], d:[{}]});
+    }
+}
+
+var append_tree = func {
+    var res = [];
+    for(var i=0; i<MAX_ITER_NUM; i+=1) {
+        append(res, {
+            a: {b: {c:[]}},
+            d: {e: {}},
+            j: {k: {l:{m:[{a:{b:{c:[{}]}}}]}}}
+        });
     }
 }
 
@@ -76,6 +111,48 @@ for(var i=0; i<10; i+=1) {
         append_hash,
         append_func,
         append_vec_in_vec,
-        append_vec_in_hash
+        append_hash_in_vec,
+        append_vec_in_hash,
+        append_hash_in_hash,
+
+        append_vec,
+        append_hash,
+        append_func,
+        append_vec_in_vec,
+        append_hash_in_vec,
+        append_vec_in_hash,
+        append_hash_in_hash,
+
+        append_hash_vec_hash,
+        append_hash_vec_hash,
+        append_hash_vec_hash,
+
+        append_tree,
+        append_tree,
+        append_tree,
+
+        append_hash_vec_hash,
+        append_hash_vec_hash,
+        append_hash_vec_hash,
+
+        append_tree,
+        append_tree,
+        append_tree,
+        
+        append_hash_vec_hash,
+        append_hash_vec_hash,
+        append_hash_vec_hash,
+
+        append_tree,
+        append_tree,
+        append_tree,
+        
+        append_hash_vec_hash,
+        append_hash_vec_hash,
+        append_hash_vec_hash,
+
+        append_tree,
+        append_tree,
+        append_tree
     );
 }