[log][tools] Fix logging on deserialized scripts

- Introduce ScriptEventType enum
- Emit log event when deserializing scripts
- Better handle deserialized and eval scripts when calculating the byte size

Bug: chromium:757467, chromium:850038
Change-Id: I082161d8d1d4238a90d3607ca8b6b4e60f2f903e
Reviewed-on: https://chromium-review.googlesource.com/1114845
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Reviewed-by: Ulan Degenbaev <ulan@chromium.org>
Reviewed-by: Sathya Gunasekaran <gsathya@chromium.org>
Reviewed-by: Yang Guo <yangguo@chromium.org>
Cr-Commit-Position: refs/heads/master@{#54061}

src/compiler.cc

@@ -974,7 +974,8 @@ BackgroundCompileTask::BackgroundCompileTask(ScriptStreamingData* source,
   // Prepare the data for the internalization phase and compilation phase, which
   // will happen in the main thread after parsing.
   ParseInfo* info = new ParseInfo(isolate);
-  LOG(isolate, ScriptEvent("background-compile", info->script_id()));
+  LOG(isolate, ScriptEvent(Logger::ScriptEventType::kBackgroundCompile,
+                           info->script_id()));
   if (V8_UNLIKELY(FLAG_runtime_stats)) {
     info->set_runtime_call_stats(new (info->zone()) RuntimeCallStats());
   } else {

src/heap/factory.cc

@@ -1541,7 +1541,7 @@ Handle<Script> Factory::NewScriptWithId(Handle<String> source, int script_id,
   script->set_host_defined_options(*empty_fixed_array());
   heap->set_script_list(
       *FixedArrayOfWeakCells::Add(isolate(), script_list(), script));
-  LOG(isolate(), ScriptEvent("create", script_id));
+  LOG(isolate(), ScriptEvent(Logger::ScriptEventType::kCreate, script_id));
   return script;
 }
 

src/log.cc

@@ -1587,10 +1587,25 @@ void Logger::CompilationCacheEvent(const char* action, const char* cache_type,
   msg.WriteToLogFile();
 }
 
-void Logger::ScriptEvent(const char* event_name, int script_id) {
+void Logger::ScriptEvent(ScriptEventType type, int script_id) {
   if (!log_->IsEnabled() || !FLAG_log_function_events) return;
   Log::MessageBuilder msg(log_);
-  msg << "script" << Logger::kNext << event_name << Logger::kNext << script_id;
+  msg << "script" << Logger::kNext;
+  switch (type) {
+    case ScriptEventType::kReserveId:
+      msg << "reserve-id";
+      break;
+    case ScriptEventType::kCreate:
+      msg << "create";
+      break;
+    case ScriptEventType::kDeserialize:
+      msg << "deserialize";
+      break;
+    case ScriptEventType::kBackgroundCompile:
+      msg << "background-compile";
+      break;
+  }
+  msg << Logger::kNext << script_id;
   msg.WriteToLogFile();
 }
 

src/log.h

@@ -124,6 +124,13 @@ class Logger : public CodeEventListener {
  public:
   enum StartEnd { START = 0, END = 1, STAMP = 2 };
 
+  enum class ScriptEventType {
+    kReserveId,
+    kCreate,
+    kDeserialize,
+    kBackgroundCompile
+  };
+
   // The separator is used to write an unescaped "," into the log.
   static const LogSeparator kNext = LogSeparator::kSeparator;
 
@@ -175,7 +182,7 @@ class Logger : public CodeEventListener {
 
   void CompilationCacheEvent(const char* action, const char* cache_type,
                              SharedFunctionInfo* sfi);
-  void ScriptEvent(const char* event_name, int script_id);
+  void ScriptEvent(ScriptEventType type, int script_id);
   void ScriptDetails(Script* script);
 
   // ==== Events logged by --log-api. ====

src/parsing/parse-info.cc

@@ -51,7 +51,7 @@ ParseInfo::ParseInfo(Isolate* isolate, AccountingAllocator* zone_allocator)
 ParseInfo::ParseInfo(Isolate* isolate)
     : ParseInfo(isolate, isolate->allocator()) {
   script_id_ = isolate->heap()->NextScriptId();
-  LOG(isolate, ScriptEvent("reserve-id", script_id_));
+  LOG(isolate, ScriptEvent(Logger::ScriptEventType::kReserveId, script_id_));
 }
 
 ParseInfo::ParseInfo(Isolate* isolate, Handle<SharedFunctionInfo> shared)

src/snapshot/deserializer.cc

@@ -169,6 +169,9 @@ HeapObject* Deserializer<AllocatorT>::PostProcessNewObject(HeapObject* obj,
     } else {
       DCHECK(CanBeDeferred(obj));
     }
+  } else if (obj->IsScript()) {
+    LOG(isolate_, ScriptEvent(Logger::ScriptEventType::kDeserialize,
+                              Script::cast(obj)->id()));
   }
 
   if (obj->IsAllocationSite()) {

src/snapshot/object-deserializer.cc

@@ -81,6 +81,8 @@ void ObjectDeserializer::CommitPostProcessedObjects() {
   for (Handle<Script> script : new_scripts()) {
     // Assign a new script id to avoid collision.
     script->set_id(isolate()->heap()->NextScriptId());
+    LOG(isolate(),
+        ScriptEvent(Logger::ScriptEventType::kDeserialize, script->id()));
     // Add script to list.
     Handle<Object> list =
         FixedArrayOfWeakCells::Add(isolate(), factory->script_list(), script);

tools/parse-processor

@@ -33,7 +33,8 @@ if [ ! -x "$d8_exec" ]; then
 fi
 
 # nm spits out 'no symbols found' messages to stderr.
-cat $log_file | $d8_exec --trace-maps --allow-natives-syntax --trace-deopt $tools_path/splaytree.js $tools_path/codemap.js \
+cat $log_file | $d8_exec --allow-natives-syntax \
+  $tools_path/splaytree.js $tools_path/codemap.js \
   $tools_path/csvparser.js $tools_path/consarray.js \
   $tools_path/profile.js $tools_path/profile_view.js \
   $tools_path/logreader.js $tools_path/arguments.js \

tools/parse-processor.js

@@ -66,13 +66,17 @@ function timestampMin(list) {
 // ===========================================================================
 class Script {
   constructor(id) {
-    this.file = '';
-    this.id = id;
-    this.isNative = false;
     if (id === void 0 || id <= 0) {
       throw new Error(`Invalid id=${id} for script`);
     }
+    this.file = '';
+    this.id = id;
+
+    this.isNative = false;
     this.isEval = false;
+    this.isBackgroundCompiled = false;
+    this.isDeserialized = false;
+
     this.funktions = [];
     this.metrics = new Map();
     this.maxNestingLevel = 0;
@@ -180,6 +184,11 @@ class Script {
 
   getOwnBytes() {
     if (this.ownBytes === -1) {
+      if (this.getBytes() === -1) {
+        if (this.isDeserialized || this.isEval) {
+          return this.ownBytes = 0;
+        }
+      }
       this.ownBytes = this.funktions.reduce(
         (bytes, each) => bytes - (each.isToplevel() ? each.getBytes() : 0),
         this.getBytes());
@@ -234,6 +243,9 @@ class Script {
     };
 
     log("  - file:         " + this.file);
+    log('  - details:      ' +
+        'isEval=' + this.isEval + ' deserialized=' + this.isDeserialized +
+        ' streamed=' + this.isBackgroundCompiled);
     info("scripts", this.getScripts());
     info("functions", all);
     info("toplevel fn", all.filter(each => each.isToplevel()));
@@ -783,8 +795,10 @@ class ParseProcessor extends LogReader {
     this.scripts = Array.from(this.idToScript.values())
       .filter(each => !each.isNative);
 
-    this.scripts.forEach(script => script.finalize());
+    this.scripts.forEach(script => {
-    this.scripts.forEach(script => script.calculateMetrics(false));
+      script.finalize();
+      script.calculateMetrics(false)
+    });
 
     this.firstEvent =
       timestampMin(this.scripts.map(each => each.firstEvent));
@@ -860,13 +874,17 @@ class ParseProcessor extends LogReader {
   }
 
   processScriptEvent(eventName, scriptId) {
-    if (eventName == 'create' || eventName == 'reserve-id') {
+    if (['create', 'reserve-id', 'deserialize'].includes(eventName)) {
       if (this.idToScript.has(scriptId)) return;
       let script = new Script(scriptId);
       this.idToScript.set(scriptId, script);
-    } else {
+      if (eventName == 'deserialize') script.isDeserialized = true;
-      console.log('Unhandled script event: ' + eventName);
+      return;
+    } else if (eventName === 'background-compile') {
+      this.idToScript.get(scriptId).isBackgroundCompiled = true;
+      return;
     }
+    console.error('Unhandled script event: ' + eventName);
   }
 
   processScriptDetails(scriptId, file, startLine, startColumn, size) {