OLD | NEW |
1 // Copyright 2011 the V8 project authors. All rights reserved. | 1 // Copyright 2011 the V8 project authors. All rights reserved. |
2 // Use of this source code is governed by a BSD-style license that can be | 2 // Use of this source code is governed by a BSD-style license that can be |
3 // found in the LICENSE file. | 3 // found in the LICENSE file. |
4 | 4 |
5 #include "src/log.h" | 5 #include "src/log.h" |
6 | 6 |
7 #include <cstdarg> | 7 #include <cstdarg> |
8 #include <memory> | 8 #include <memory> |
9 #include <sstream> | 9 #include <sstream> |
10 | 10 |
(...skipping 825 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
836 uintptr_t start, uintptr_t end, | 836 uintptr_t start, uintptr_t end, |
837 intptr_t aslr_slide) { | 837 intptr_t aslr_slide) { |
838 if (!log_->IsEnabled() || !FLAG_prof_cpp) return; | 838 if (!log_->IsEnabled() || !FLAG_prof_cpp) return; |
839 Log::MessageBuilder msg(log_); | 839 Log::MessageBuilder msg(log_); |
840 msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR | 840 msg.Append("shared-library,\"%s\",0x%08" V8PRIxPTR ",0x%08" V8PRIxPTR |
841 ",%" V8PRIdPTR, | 841 ",%" V8PRIdPTR, |
842 library_path.c_str(), start, end, aslr_slide); | 842 library_path.c_str(), start, end, aslr_slide); |
843 msg.WriteToLogFile(); | 843 msg.WriteToLogFile(); |
844 } | 844 } |
845 | 845 |
846 | 846 void Logger::CodeDeoptEvent(Code* code, DeoptKind kind, Address pc, |
847 void Logger::CodeDeoptEvent(Code* code, Address pc, int fp_to_sp_delta) { | 847 int fp_to_sp_delta) { |
848 if (!log_->IsEnabled() || !FLAG_log_internal_timer_events) return; | 848 if (!log_->IsEnabled()) return; |
| 849 Deoptimizer::DeoptInfo info = Deoptimizer::GetDeoptInfo(code, pc); |
849 Log::MessageBuilder msg(log_); | 850 Log::MessageBuilder msg(log_); |
850 int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds()); | 851 int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds()); |
851 msg.Append("code-deopt,%d,%d", since_epoch, code->CodeSize()); | 852 msg.Append("code-deopt,%d,%d,", since_epoch, code->CodeSize()); |
| 853 msg.AppendAddress(code->address()); |
| 854 |
| 855 // Deoptimization position. |
| 856 std::ostringstream deopt_location; |
| 857 int inlining_id = -1; |
| 858 int script_offset = -1; |
| 859 if (info.position.IsKnown()) { |
| 860 info.position.Print(deopt_location, code); |
| 861 inlining_id = info.position.InliningId(); |
| 862 script_offset = info.position.ScriptOffset(); |
| 863 } else { |
| 864 deopt_location << "<unknown>"; |
| 865 } |
| 866 msg.Append(",%d,%d,", inlining_id, script_offset); |
| 867 switch (kind) { |
| 868 case kLazy: |
| 869 msg.Append("\"lazy\","); |
| 870 break; |
| 871 case kSoft: |
| 872 msg.Append("\"soft\","); |
| 873 break; |
| 874 case kEager: |
| 875 msg.Append("\"eager\","); |
| 876 break; |
| 877 } |
| 878 msg.AppendDoubleQuotedString(deopt_location.str().c_str()); |
| 879 msg.Append(","); |
| 880 msg.AppendDoubleQuotedString(DeoptimizeReasonToString(info.deopt_reason)); |
852 msg.WriteToLogFile(); | 881 msg.WriteToLogFile(); |
853 } | 882 } |
854 | 883 |
855 | 884 |
856 void Logger::CurrentTimeEvent() { | 885 void Logger::CurrentTimeEvent() { |
857 if (!log_->IsEnabled()) return; | 886 if (!log_->IsEnabled()) return; |
858 DCHECK(FLAG_log_timer_events || FLAG_prof_cpp); | 887 DCHECK(FLAG_log_timer_events || FLAG_prof_cpp); |
859 Log::MessageBuilder msg(log_); | 888 Log::MessageBuilder msg(log_); |
860 int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds()); | 889 int since_epoch = static_cast<int>(timer_.Elapsed().InMicroseconds()); |
861 msg.Append("current-time,%d", since_epoch); | 890 msg.Append("current-time,%d", since_epoch); |
(...skipping 103 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
965 } | 994 } |
966 | 995 |
967 | 996 |
968 void Logger::CallbackEventInternal(const char* prefix, Name* name, | 997 void Logger::CallbackEventInternal(const char* prefix, Name* name, |
969 Address entry_point) { | 998 Address entry_point) { |
970 if (!FLAG_log_code || !log_->IsEnabled()) return; | 999 if (!FLAG_log_code || !log_->IsEnabled()) return; |
971 Log::MessageBuilder msg(log_); | 1000 Log::MessageBuilder msg(log_); |
972 msg.Append("%s,%s,-2,", | 1001 msg.Append("%s,%s,-2,", |
973 kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT], | 1002 kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT], |
974 kLogEventsNames[CodeEventListener::CALLBACK_TAG]); | 1003 kLogEventsNames[CodeEventListener::CALLBACK_TAG]); |
| 1004 int timestamp = timer_.IsStarted() |
| 1005 ? static_cast<int>(timer_.Elapsed().InMicroseconds()) |
| 1006 : -1; |
| 1007 msg.Append("%d,", timestamp); |
975 msg.AppendAddress(entry_point); | 1008 msg.AppendAddress(entry_point); |
976 if (name->IsString()) { | 1009 if (name->IsString()) { |
977 std::unique_ptr<char[]> str = | 1010 std::unique_ptr<char[]> str = |
978 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); | 1011 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); |
979 msg.Append(",1,\"%s%s\"", prefix, str.get()); | 1012 msg.Append(",1,\"%s%s\"", prefix, str.get()); |
980 } else { | 1013 } else { |
981 Symbol* symbol = Symbol::cast(name); | 1014 Symbol* symbol = Symbol::cast(name); |
982 if (symbol->name()->IsUndefined(symbol->GetIsolate())) { | 1015 if (symbol->name()->IsUndefined(symbol->GetIsolate())) { |
983 msg.Append(",1,symbol(hash %x)", symbol->Hash()); | 1016 msg.Append(",1,symbol(hash %x)", symbol->Hash()); |
984 } else { | 1017 } else { |
(...skipping 15 matching lines...) Expand all Loading... |
1000 | 1033 |
1001 void Logger::GetterCallbackEvent(Name* name, Address entry_point) { | 1034 void Logger::GetterCallbackEvent(Name* name, Address entry_point) { |
1002 CallbackEventInternal("get ", name, entry_point); | 1035 CallbackEventInternal("get ", name, entry_point); |
1003 } | 1036 } |
1004 | 1037 |
1005 | 1038 |
1006 void Logger::SetterCallbackEvent(Name* name, Address entry_point) { | 1039 void Logger::SetterCallbackEvent(Name* name, Address entry_point) { |
1007 CallbackEventInternal("set ", name, entry_point); | 1040 CallbackEventInternal("set ", name, entry_point); |
1008 } | 1041 } |
1009 | 1042 |
1010 static void AppendCodeCreateHeader(Log::MessageBuilder* msg, | 1043 namespace { |
1011 CodeEventListener::LogEventsAndTags tag, | 1044 |
1012 AbstractCode* code) { | 1045 void AppendCodeCreateHeader(Log::MessageBuilder* msg, |
| 1046 CodeEventListener::LogEventsAndTags tag, |
| 1047 AbstractCode* code, base::ElapsedTimer* timer) { |
1013 DCHECK(msg); | 1048 DCHECK(msg); |
1014 msg->Append("%s,%s,%d,", | 1049 msg->Append("%s,%s,%d,", |
1015 kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT], | 1050 kLogEventsNames[CodeEventListener::CODE_CREATION_EVENT], |
1016 kLogEventsNames[tag], code->kind()); | 1051 kLogEventsNames[tag], code->kind()); |
| 1052 int timestamp = timer->IsStarted() |
| 1053 ? static_cast<int>(timer->Elapsed().InMicroseconds()) |
| 1054 : -1; |
| 1055 msg->Append("%d,", timestamp); |
1017 msg->AppendAddress(code->address()); | 1056 msg->AppendAddress(code->address()); |
1018 msg->Append(",%d,", code->ExecutableSize()); | 1057 msg->Append(",%d,", code->ExecutableSize()); |
1019 } | 1058 } |
1020 | 1059 |
| 1060 } // namespace |
| 1061 |
1021 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, | 1062 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, |
1022 AbstractCode* code, const char* comment) { | 1063 AbstractCode* code, const char* comment) { |
1023 if (!is_logging_code_events()) return; | 1064 if (!is_logging_code_events()) return; |
1024 if (!FLAG_log_code || !log_->IsEnabled()) return; | 1065 if (!FLAG_log_code || !log_->IsEnabled()) return; |
1025 Log::MessageBuilder msg(log_); | 1066 Log::MessageBuilder msg(log_); |
1026 AppendCodeCreateHeader(&msg, tag, code); | 1067 AppendCodeCreateHeader(&msg, tag, code, &timer_); |
1027 msg.AppendDoubleQuotedString(comment); | 1068 msg.AppendDoubleQuotedString(comment); |
1028 msg.WriteToLogFile(); | 1069 msg.WriteToLogFile(); |
1029 } | 1070 } |
1030 | 1071 |
1031 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, | 1072 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, |
1032 AbstractCode* code, Name* name) { | 1073 AbstractCode* code, Name* name) { |
1033 if (!is_logging_code_events()) return; | 1074 if (!is_logging_code_events()) return; |
1034 if (!FLAG_log_code || !log_->IsEnabled()) return; | 1075 if (!FLAG_log_code || !log_->IsEnabled()) return; |
1035 Log::MessageBuilder msg(log_); | 1076 Log::MessageBuilder msg(log_); |
1036 AppendCodeCreateHeader(&msg, tag, code); | 1077 AppendCodeCreateHeader(&msg, tag, code, &timer_); |
1037 if (name->IsString()) { | 1078 if (name->IsString()) { |
1038 msg.Append('"'); | 1079 msg.Append('"'); |
1039 msg.AppendDetailed(String::cast(name), false); | 1080 msg.AppendDetailed(String::cast(name), false); |
1040 msg.Append('"'); | 1081 msg.Append('"'); |
1041 } else { | 1082 } else { |
1042 msg.AppendSymbolName(Symbol::cast(name)); | 1083 msg.AppendSymbolName(Symbol::cast(name)); |
1043 } | 1084 } |
1044 msg.WriteToLogFile(); | 1085 msg.WriteToLogFile(); |
1045 } | 1086 } |
1046 | 1087 |
1047 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, | 1088 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, |
1048 AbstractCode* code, SharedFunctionInfo* shared, | 1089 AbstractCode* code, SharedFunctionInfo* shared, |
1049 Name* name) { | 1090 Name* name) { |
1050 if (!is_logging_code_events()) return; | 1091 if (!is_logging_code_events()) return; |
1051 if (!FLAG_log_code || !log_->IsEnabled()) return; | 1092 if (!FLAG_log_code || !log_->IsEnabled()) return; |
1052 if (code == AbstractCode::cast( | 1093 if (code == AbstractCode::cast( |
1053 isolate_->builtins()->builtin(Builtins::kCompileLazy))) { | 1094 isolate_->builtins()->builtin(Builtins::kCompileLazy))) { |
1054 return; | 1095 return; |
1055 } | 1096 } |
1056 | 1097 |
1057 Log::MessageBuilder msg(log_); | 1098 Log::MessageBuilder msg(log_); |
1058 AppendCodeCreateHeader(&msg, tag, code); | 1099 AppendCodeCreateHeader(&msg, tag, code, &timer_); |
1059 if (name->IsString()) { | 1100 if (name->IsString()) { |
1060 std::unique_ptr<char[]> str = | 1101 std::unique_ptr<char[]> str = |
1061 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); | 1102 String::cast(name)->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); |
1062 msg.Append("\"%s\"", str.get()); | 1103 msg.Append("\"%s\"", str.get()); |
1063 } else { | 1104 } else { |
1064 msg.AppendSymbolName(Symbol::cast(name)); | 1105 msg.AppendSymbolName(Symbol::cast(name)); |
1065 } | 1106 } |
1066 msg.Append(','); | 1107 msg.Append(','); |
1067 msg.AppendAddress(shared->address()); | 1108 msg.AppendAddress(shared->address()); |
1068 msg.Append(",%s", ComputeMarker(shared, code)); | 1109 msg.Append(",%s", ComputeMarker(shared, code)); |
1069 msg.WriteToLogFile(); | 1110 msg.WriteToLogFile(); |
1070 } | 1111 } |
1071 | 1112 |
1072 | 1113 |
1073 // Although, it is possible to extract source and line from | 1114 // Although, it is possible to extract source and line from |
1074 // the SharedFunctionInfo object, we left it to caller | 1115 // the SharedFunctionInfo object, we left it to caller |
1075 // to leave logging functions free from heap allocations. | 1116 // to leave logging functions free from heap allocations. |
1076 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, | 1117 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, |
1077 AbstractCode* code, SharedFunctionInfo* shared, | 1118 AbstractCode* code, SharedFunctionInfo* shared, |
1078 Name* source, int line, int column) { | 1119 Name* source, int line, int column) { |
1079 if (!is_logging_code_events()) return; | 1120 if (!is_logging_code_events()) return; |
1080 if (!FLAG_log_code || !log_->IsEnabled()) return; | 1121 if (!FLAG_log_code || !log_->IsEnabled()) return; |
1081 Log::MessageBuilder msg(log_); | 1122 Log::MessageBuilder msg(log_); |
1082 AppendCodeCreateHeader(&msg, tag, code); | 1123 AppendCodeCreateHeader(&msg, tag, code, &timer_); |
1083 std::unique_ptr<char[]> name = | 1124 std::unique_ptr<char[]> name = |
1084 shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); | 1125 shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); |
1085 msg.Append("\"%s ", name.get()); | 1126 msg.Append("\"%s ", name.get()); |
1086 if (source->IsString()) { | 1127 if (source->IsString()) { |
1087 std::unique_ptr<char[]> sourcestr = String::cast(source)->ToCString( | 1128 std::unique_ptr<char[]> sourcestr = String::cast(source)->ToCString( |
1088 DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); | 1129 DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); |
1089 msg.Append("%s", sourcestr.get()); | 1130 msg.Append("%s", sourcestr.get()); |
1090 } else { | 1131 } else { |
1091 msg.AppendSymbolName(Symbol::cast(source)); | 1132 msg.AppendSymbolName(Symbol::cast(source)); |
1092 } | 1133 } |
1093 msg.Append(":%d:%d\",", line, column); | 1134 msg.Append(":%d:%d\",", line, column); |
1094 msg.AppendAddress(shared->address()); | 1135 msg.AppendAddress(shared->address()); |
1095 msg.Append(",%s", ComputeMarker(shared, code)); | 1136 msg.Append(",%s", ComputeMarker(shared, code)); |
1096 msg.WriteToLogFile(); | 1137 msg.WriteToLogFile(); |
1097 } | 1138 } |
1098 | 1139 |
1099 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, | 1140 void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag, |
1100 AbstractCode* code, int args_count) { | 1141 AbstractCode* code, int args_count) { |
1101 if (!is_logging_code_events()) return; | 1142 if (!is_logging_code_events()) return; |
1102 if (!FLAG_log_code || !log_->IsEnabled()) return; | 1143 if (!FLAG_log_code || !log_->IsEnabled()) return; |
1103 Log::MessageBuilder msg(log_); | 1144 Log::MessageBuilder msg(log_); |
1104 AppendCodeCreateHeader(&msg, tag, code); | 1145 AppendCodeCreateHeader(&msg, tag, code, &timer_); |
1105 msg.Append("\"args_count: %d\"", args_count); | 1146 msg.Append("\"args_count: %d\"", args_count); |
1106 msg.WriteToLogFile(); | 1147 msg.WriteToLogFile(); |
1107 } | 1148 } |
1108 | 1149 |
1109 void Logger::CodeDisableOptEvent(AbstractCode* code, | 1150 void Logger::CodeDisableOptEvent(AbstractCode* code, |
1110 SharedFunctionInfo* shared) { | 1151 SharedFunctionInfo* shared) { |
1111 if (!is_logging_code_events()) return; | 1152 if (!is_logging_code_events()) return; |
1112 if (!FLAG_log_code || !log_->IsEnabled()) return; | 1153 if (!FLAG_log_code || !log_->IsEnabled()) return; |
1113 Log::MessageBuilder msg(log_); | 1154 Log::MessageBuilder msg(log_); |
1114 msg.Append("%s,", kLogEventsNames[CodeEventListener::CODE_DISABLE_OPT_EVENT]); | 1155 msg.Append("%s,", kLogEventsNames[CodeEventListener::CODE_DISABLE_OPT_EVENT]); |
1115 std::unique_ptr<char[]> name = | 1156 std::unique_ptr<char[]> name = |
1116 shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); | 1157 shared->DebugName()->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL); |
1117 msg.Append("\"%s\",", name.get()); | 1158 msg.Append("\"%s\",", name.get()); |
1118 msg.Append("\"%s\"", GetBailoutReason(shared->disable_optimization_reason())); | 1159 msg.Append("\"%s\"", GetBailoutReason(shared->disable_optimization_reason())); |
1119 msg.WriteToLogFile(); | 1160 msg.WriteToLogFile(); |
1120 } | 1161 } |
1121 | 1162 |
1122 | 1163 |
1123 void Logger::CodeMovingGCEvent() { | 1164 void Logger::CodeMovingGCEvent() { |
1124 if (!is_logging_code_events()) return; | 1165 if (!is_logging_code_events()) return; |
1125 if (!log_->IsEnabled() || !FLAG_ll_prof) return; | 1166 if (!log_->IsEnabled() || !FLAG_ll_prof) return; |
1126 base::OS::SignalCodeMovingGC(); | 1167 base::OS::SignalCodeMovingGC(); |
1127 } | 1168 } |
1128 | 1169 |
1129 void Logger::RegExpCodeCreateEvent(AbstractCode* code, String* source) { | 1170 void Logger::RegExpCodeCreateEvent(AbstractCode* code, String* source) { |
1130 if (!is_logging_code_events()) return; | 1171 if (!is_logging_code_events()) return; |
1131 if (!FLAG_log_code || !log_->IsEnabled()) return; | 1172 if (!FLAG_log_code || !log_->IsEnabled()) return; |
1132 Log::MessageBuilder msg(log_); | 1173 Log::MessageBuilder msg(log_); |
1133 AppendCodeCreateHeader(&msg, CodeEventListener::REG_EXP_TAG, code); | 1174 AppendCodeCreateHeader(&msg, CodeEventListener::REG_EXP_TAG, code, &timer_); |
1134 msg.Append('"'); | 1175 msg.Append('"'); |
1135 msg.AppendDetailed(source, false); | 1176 msg.AppendDetailed(source, false); |
1136 msg.Append('"'); | 1177 msg.Append('"'); |
1137 msg.WriteToLogFile(); | 1178 msg.WriteToLogFile(); |
1138 } | 1179 } |
1139 | 1180 |
1140 void Logger::CodeMoveEvent(AbstractCode* from, Address to) { | 1181 void Logger::CodeMoveEvent(AbstractCode* from, Address to) { |
1141 if (!is_logging_code_events()) return; | 1182 if (!is_logging_code_events()) return; |
1142 MoveEventInternal(CodeEventListener::CODE_MOVE_EVENT, from->address(), to); | 1183 MoveEventInternal(CodeEventListener::CODE_MOVE_EVENT, from->address(), to); |
1143 } | 1184 } |
(...skipping 712 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
1856 | 1897 |
1857 if (profiler_listener_.get() != nullptr) { | 1898 if (profiler_listener_.get() != nullptr) { |
1858 removeCodeEventListener(profiler_listener_.get()); | 1899 removeCodeEventListener(profiler_listener_.get()); |
1859 } | 1900 } |
1860 | 1901 |
1861 return log_->Close(); | 1902 return log_->Close(); |
1862 } | 1903 } |
1863 | 1904 |
1864 } // namespace internal | 1905 } // namespace internal |
1865 } // namespace v8 | 1906 } // namespace v8 |
OLD | NEW |