OLD | NEW |
1 // Copyright 2006-2009 the V8 project authors. All rights reserved. | 1 // Copyright 2006-2009 the V8 project authors. All rights reserved. |
2 // | 2 // |
3 // Tests of logging functions from log.h | 3 // Tests of logging functions from log.h |
4 | 4 |
5 #ifdef ENABLE_LOGGING_AND_PROFILING | 5 #ifdef ENABLE_LOGGING_AND_PROFILING |
6 | 6 |
7 #include "v8.h" | 7 #include "v8.h" |
8 | 8 |
9 #include "log.h" | 9 #include "log.h" |
10 | |
11 #include "cctest.h" | 10 #include "cctest.h" |
12 | 11 |
| 12 using v8::internal::Address; |
13 using v8::internal::Logger; | 13 using v8::internal::Logger; |
14 | 14 |
| 15 namespace i = v8::internal; |
| 16 |
15 static void SetUp() { | 17 static void SetUp() { |
16 // Log to memory buffer. | 18 // Log to memory buffer. |
17 v8::internal::FLAG_logfile = "*"; | 19 i::FLAG_logfile = "*"; |
18 v8::internal::FLAG_log = true; | 20 i::FLAG_log = true; |
19 Logger::Setup(); | 21 Logger::Setup(); |
20 } | 22 } |
21 | 23 |
22 static void TearDown() { | 24 static void TearDown() { |
23 Logger::TearDown(); | 25 Logger::TearDown(); |
24 } | 26 } |
25 | 27 |
26 | 28 |
27 TEST(EmptyLog) { | 29 TEST(EmptyLog) { |
28 SetUp(); | 30 SetUp(); |
(...skipping 67 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
96 CHECK_EQ(0, Logger::GetLogLines(all_lines_len + 100, NULL, 1)); | 98 CHECK_EQ(0, Logger::GetLogLines(all_lines_len + 100, NULL, 1)); |
97 CHECK_EQ(0, Logger::GetLogLines(all_lines_len + 100, NULL, 100)); | 99 CHECK_EQ(0, Logger::GetLogLines(all_lines_len + 100, NULL, 100)); |
98 CHECK_EQ(0, Logger::GetLogLines(10 * 1024 * 1024, NULL, 1)); | 100 CHECK_EQ(0, Logger::GetLogLines(10 * 1024 * 1024, NULL, 1)); |
99 CHECK_EQ(0, Logger::GetLogLines(10 * 1024 * 1024, NULL, 100)); | 101 CHECK_EQ(0, Logger::GetLogLines(10 * 1024 * 1024, NULL, 100)); |
100 TearDown(); | 102 TearDown(); |
101 } | 103 } |
102 | 104 |
103 | 105 |
104 TEST(MemoryLoggingTurnedOff) { | 106 TEST(MemoryLoggingTurnedOff) { |
105 // Log to stdout | 107 // Log to stdout |
106 v8::internal::FLAG_logfile = "-"; | 108 i::FLAG_logfile = "-"; |
107 v8::internal::FLAG_log = true; | 109 i::FLAG_log = true; |
108 Logger::Setup(); | 110 Logger::Setup(); |
109 CHECK_EQ(0, Logger::GetLogLines(0, NULL, 0)); | 111 CHECK_EQ(0, Logger::GetLogLines(0, NULL, 0)); |
110 CHECK_EQ(0, Logger::GetLogLines(100, NULL, 0)); | 112 CHECK_EQ(0, Logger::GetLogLines(100, NULL, 0)); |
111 CHECK_EQ(0, Logger::GetLogLines(0, NULL, 100)); | 113 CHECK_EQ(0, Logger::GetLogLines(0, NULL, 100)); |
112 CHECK_EQ(0, Logger::GetLogLines(100, NULL, 100)); | 114 CHECK_EQ(0, Logger::GetLogLines(100, NULL, 100)); |
113 Logger::TearDown(); | 115 Logger::TearDown(); |
114 } | 116 } |
115 | 117 |
116 | 118 |
| 119 static inline bool IsStringEqualTo(const char* r, const char* s) { |
| 120 return strncmp(r, s, strlen(r)) == 0; |
| 121 } |
| 122 |
| 123 |
| 124 static bool Consume(const char* str, char** buf) { |
| 125 if (IsStringEqualTo(str, *buf)) { |
| 126 *buf += strlen(str); |
| 127 return true; |
| 128 } |
| 129 return false; |
| 130 } |
| 131 |
| 132 |
| 133 static void ParseAddress(char* start, Address* min_addr, Address* max_addr) { |
| 134 Address addr = reinterpret_cast<Address>(strtoll(start, NULL, 16)); |
| 135 if (addr < *min_addr) *min_addr = addr; |
| 136 if (addr > *max_addr) *max_addr = addr; |
| 137 } |
| 138 |
| 139 |
| 140 static Address ConsumeAddress( |
| 141 char** start, Address min_addr, Address max_addr) { |
| 142 char* end_ptr; |
| 143 Address addr = reinterpret_cast<Address>(strtoll(*start, &end_ptr, 16)); |
| 144 CHECK_GE(addr, min_addr); |
| 145 CHECK_GE(max_addr, addr); |
| 146 *start = end_ptr; |
| 147 return addr; |
| 148 } |
| 149 |
| 150 |
| 151 namespace { |
| 152 |
| 153 // A code entity is a pointer to a position of code-creation event in buffer log |
| 154 // offset to a point where entity size begins, i.e.: '255,"func"\n'. This makes |
| 155 // comparing code entities pretty easy. |
| 156 typedef char* CodeEntityInfo; |
| 157 |
| 158 // A structure used to return log parsing results. |
| 159 class ParseLogResult { |
| 160 public: |
| 161 ParseLogResult() |
| 162 : min_addr(reinterpret_cast<Address>(-1)), |
| 163 max_addr(reinterpret_cast<Address>(0)), |
| 164 entities_map(NULL), entities(NULL), |
| 165 max_entities(0) {}; |
| 166 |
| 167 ~ParseLogResult() { |
| 168 // See allocation code below. |
| 169 if (entities_map != NULL) { |
| 170 i::DeleteArray(entities_map - 1); |
| 171 } |
| 172 i::DeleteArray(entities); |
| 173 } |
| 174 |
| 175 void AllocateEntities() { |
| 176 // Make sure that the test doesn't operate on a bogus log. |
| 177 CHECK_GT(max_entities, 0); |
| 178 CHECK_GT(min_addr, 0); |
| 179 CHECK_GT(max_addr, min_addr); |
| 180 |
| 181 entities = i::NewArray<CodeEntityInfo>(max_entities); |
| 182 for (int i = 0; i < max_entities; ++i) { |
| 183 entities[i] = NULL; |
| 184 } |
| 185 // We're adding fake items at [-1] and [size + 1] to simplify |
| 186 // comparison code. |
| 187 const int map_length = max_addr - min_addr + 1 + 2; // 2 fakes. |
| 188 entities_map = i::NewArray<int>(map_length); |
| 189 for (int i = 0; i < map_length; ++i) { |
| 190 entities_map[i] = -1; |
| 191 } |
| 192 entities_map += 1; // Hide the -1 item, this is compensated on delete. |
| 193 } |
| 194 |
| 195 // Minimal code entity address. |
| 196 Address min_addr; |
| 197 // Maximal code entity address. |
| 198 Address max_addr; |
| 199 // Memory map of entities start addresses. Biased by min_addr. |
| 200 int* entities_map; |
| 201 // An array of code entities. |
| 202 CodeEntityInfo* entities; |
| 203 // Maximal entities count. Actual entities count can be lower, |
| 204 // empty entity slots are pointing to NULL. |
| 205 int max_entities; |
| 206 }; |
| 207 |
| 208 } // namespace |
| 209 |
| 210 |
| 211 typedef void (*ParserBlock)(char* start, char* end, ParseLogResult* result); |
| 212 |
| 213 static void ParserCycle( |
| 214 char* start, char* end, ParseLogResult* result, |
| 215 ParserBlock block_creation, ParserBlock block_delete, |
| 216 ParserBlock block_move) { |
| 217 |
| 218 const char* code_creation = "code-creation,"; |
| 219 const char* code_delete = "code-delete,"; |
| 220 const char* code_move = "code-move,"; |
| 221 |
| 222 const char* lazy_compile = "LazyCompile,"; |
| 223 const char* script = "Script,"; |
| 224 const char* function = "Function,"; |
| 225 |
| 226 while (start < end) { |
| 227 if (Consume(code_creation, &start)) { |
| 228 if (Consume(lazy_compile, &start) |
| 229 || Consume(script, &start) |
| 230 || Consume(function, &start)) { |
| 231 block_creation(start, end, result); |
| 232 } |
| 233 } else if (Consume(code_delete, &start)) { |
| 234 block_delete(start, end, result); |
| 235 } else if (Consume(code_move, &start)) { |
| 236 block_move(start, end, result); |
| 237 } |
| 238 while (start < end && *start != '\n') ++start; |
| 239 ++start; |
| 240 } |
| 241 } |
| 242 |
| 243 |
| 244 static void Pass1CodeCreation(char* start, char* end, ParseLogResult* result) { |
| 245 ParseAddress(start, &result->min_addr, &result->max_addr); |
| 246 ++result->max_entities; |
| 247 } |
| 248 |
| 249 |
| 250 static void Pass1CodeDelete(char* start, char* end, ParseLogResult* result) { |
| 251 ParseAddress(start, &result->min_addr, &result->max_addr); |
| 252 } |
| 253 |
| 254 |
| 255 static void Pass1CodeMove(char* start, char* end, ParseLogResult* result) { |
| 256 // Skip old address. |
| 257 while (start < end && *start != ',') ++start; |
| 258 CHECK_GT(end, start); |
| 259 ++start; // Skip ','. |
| 260 ParseAddress(start, &result->min_addr, &result->max_addr); |
| 261 } |
| 262 |
| 263 |
| 264 static void Pass2CodeCreation(char* start, char* end, ParseLogResult* result) { |
| 265 Address addr = ConsumeAddress(&start, result->min_addr, result->max_addr); |
| 266 CHECK_GT(end, start); |
| 267 ++start; // Skip ','. |
| 268 |
| 269 int idx = addr - result->min_addr; |
| 270 result->entities_map[idx] = -1; |
| 271 for (int i = 0; i < result->max_entities; ++i) { |
| 272 // Find an empty slot and fill it. |
| 273 if (result->entities[i] == NULL) { |
| 274 result->entities[i] = start; |
| 275 result->entities_map[idx] = i; |
| 276 break; |
| 277 } |
| 278 } |
| 279 // Make sure that a slot was found. |
| 280 CHECK_GE(result->entities_map[idx], 0); |
| 281 } |
| 282 |
| 283 |
| 284 static void Pass2CodeDelete(char* start, char* end, ParseLogResult* result) { |
| 285 Address addr = ConsumeAddress(&start, result->min_addr, result->max_addr); |
| 286 int idx = addr - result->min_addr; |
| 287 // There can be code deletes that are not related to JS code. |
| 288 if (result->entities_map[idx] >= 0) { |
| 289 result->entities[result->entities_map[idx]] = NULL; |
| 290 result->entities_map[idx] = -1; |
| 291 } |
| 292 } |
| 293 |
| 294 |
| 295 static void Pass2CodeMove(char* start, char* end, ParseLogResult* result) { |
| 296 Address from_addr = ConsumeAddress( |
| 297 &start, result->min_addr, result->max_addr); |
| 298 CHECK_GT(end, start); |
| 299 ++start; // Skip ','. |
| 300 Address to_addr = ConsumeAddress(&start, result->min_addr, result->max_addr); |
| 301 CHECK_GT(end, start); |
| 302 |
| 303 int from_idx = from_addr - result->min_addr; |
| 304 int to_idx = to_addr - result->min_addr; |
| 305 // There can be code moves that are not related to JS code. |
| 306 if (from_idx != to_idx && result->entities_map[from_idx] >= 0) { |
| 307 CHECK_EQ(-1, result->entities_map[to_idx]); |
| 308 result->entities_map[to_idx] = result->entities_map[from_idx]; |
| 309 result->entities_map[from_idx] = -1; |
| 310 }; |
| 311 } |
| 312 |
| 313 |
| 314 static void ParseLog(char* start, char* end, ParseLogResult* result) { |
| 315 // Pass 1: Calculate boundaries of addresses and entities count. |
| 316 ParserCycle(start, end, result, |
| 317 Pass1CodeCreation, Pass1CodeDelete, Pass1CodeMove); |
| 318 |
| 319 printf("min_addr: %p, max_addr: %p, entities: %d\n", |
| 320 result->min_addr, result->max_addr, result->max_entities); |
| 321 |
| 322 result->AllocateEntities(); |
| 323 |
| 324 // Pass 2: Fill in code entries data. |
| 325 ParserCycle(start, end, result, |
| 326 Pass2CodeCreation, Pass2CodeDelete, Pass2CodeMove); |
| 327 } |
| 328 |
| 329 |
| 330 static inline void PrintCodeEntityInfo(CodeEntityInfo entity) { |
| 331 const int max_len = 50; |
| 332 if (entity != NULL) { |
| 333 char* eol = strchr(entity, '\n'); |
| 334 int len = eol - entity; |
| 335 len = len <= max_len ? len : max_len; |
| 336 printf("%-*.*s ", max_len, len, entity); |
| 337 } else { |
| 338 printf("%*s", max_len + 1, ""); |
| 339 } |
| 340 } |
| 341 |
| 342 |
| 343 static void PrintCodeEntitiesInfo( |
| 344 bool is_equal, Address addr, |
| 345 CodeEntityInfo l_entity, CodeEntityInfo r_entity) { |
| 346 printf("%c %p ", is_equal ? ' ' : '*', addr); |
| 347 PrintCodeEntityInfo(l_entity); |
| 348 PrintCodeEntityInfo(r_entity); |
| 349 printf("\n"); |
| 350 } |
| 351 |
| 352 |
| 353 static inline int StrChrLen(const char* s, char c) { |
| 354 return strchr(s, c) - s; |
| 355 } |
| 356 |
| 357 |
| 358 static bool AreFuncSizesEqual(CodeEntityInfo ref_s, CodeEntityInfo new_s) { |
| 359 int ref_len = StrChrLen(ref_s, ','); |
| 360 int new_len = StrChrLen(new_s, ','); |
| 361 return ref_len == new_len && strncmp(ref_s, new_s, ref_len) == 0; |
| 362 } |
| 363 |
| 364 |
| 365 static bool AreFuncNamesEqual(CodeEntityInfo ref_s, CodeEntityInfo new_s) { |
| 366 // Skip size. |
| 367 ref_s = strchr(ref_s, ',') + 1; |
| 368 new_s = strchr(new_s, ',') + 1; |
| 369 int ref_len = StrChrLen(ref_s, '\n'); |
| 370 int new_len = StrChrLen(new_s, '\n'); |
| 371 // If reference is anonymous (""), it's OK to have anything in new. |
| 372 if (ref_len == 2) return true; |
| 373 // A special case for ErrorPrototype. Haven't yet figured out why they |
| 374 // are different. |
| 375 const char* error_prototype = "\"ErrorPrototype"; |
| 376 if (IsStringEqualTo(error_prototype, ref_s) |
| 377 && IsStringEqualTo(error_prototype, new_s)) { |
| 378 return true; |
| 379 } |
| 380 return ref_len == new_len && strncmp(ref_s, new_s, ref_len) == 0; |
| 381 } |
| 382 |
| 383 |
| 384 static bool AreEntitiesEqual(CodeEntityInfo ref_e, CodeEntityInfo new_e) { |
| 385 if (ref_e == NULL && new_e != NULL) return true; |
| 386 if (ref_e != NULL && new_e != NULL) { |
| 387 return AreFuncSizesEqual(ref_e, new_e) && AreFuncNamesEqual(ref_e, new_e); |
| 388 } |
| 389 if (ref_e != NULL && new_e == NULL) { |
| 390 // args_count entities (argument adapters) are not found by heap traversal, |
| 391 // but they are not needed because they doesn't contain any code. |
| 392 ref_e = strchr(ref_e, ',') + 1; |
| 393 const char* args_count = "\"args_count:"; |
| 394 return IsStringEqualTo(args_count, ref_e); |
| 395 } |
| 396 return false; |
| 397 } |
| 398 |
| 399 |
| 400 // Test that logging of code create / move / delete events |
| 401 // is equivalent to traversal of a resulting heap. |
| 402 TEST(EquivalenceOfLoggingAndTraversal) { |
| 403 i::FLAG_logfile = "*"; |
| 404 i::FLAG_log = true; |
| 405 i::FLAG_log_code = true; |
| 406 |
| 407 // Make sure objects move. |
| 408 bool saved_always_compact = i::FLAG_always_compact; |
| 409 if (!i::FLAG_never_compact) { |
| 410 i::FLAG_always_compact = true; |
| 411 } |
| 412 |
| 413 v8::Persistent<v8::Context> env = v8::Context::New(); |
| 414 v8::HandleScope scope; |
| 415 env->Enter(); |
| 416 |
| 417 // Compile and run a function that creates other functions. |
| 418 v8::Script::Compile(v8::String::New( |
| 419 "(function f() {\n" |
| 420 " var rets = [];\n" |
| 421 " for (var i = 0; i < 100; ++i) {\n" |
| 422 " rets.push((function inc(n) { return n + 1; })(i));\n" |
| 423 " }\n" |
| 424 "})();"))->Run(); |
| 425 i::Heap::CollectAllGarbage(); |
| 426 |
| 427 i::EmbeddedVector<char,204800> buffer; |
| 428 int log_size; |
| 429 ParseLogResult ref_result; |
| 430 |
| 431 // Retrieve the log. |
| 432 { |
| 433 // Make sure that no GCs occur prior to LogCompiledFunctions call. |
| 434 i::AssertNoAllocation no_alloc; |
| 435 |
| 436 log_size = Logger::GetLogLines(0, buffer.start(), buffer.length()); |
| 437 CHECK_GT(log_size, 0); |
| 438 CHECK_GT(buffer.length(), log_size); |
| 439 |
| 440 // Fill a map of compiled code objects. |
| 441 ParseLog(buffer.start(), buffer.start() + log_size, &ref_result); |
| 442 } |
| 443 |
| 444 // Iterate heap to find compiled functions, will write to log. |
| 445 i::Logger::LogCompiledFunctions(); |
| 446 char* new_log_start = buffer.start() + log_size; |
| 447 const int new_log_size = Logger::GetLogLines( |
| 448 log_size, new_log_start, buffer.length() - log_size); |
| 449 CHECK_GT(new_log_size, 0); |
| 450 CHECK_GT(buffer.length(), log_size + new_log_size); |
| 451 |
| 452 // Fill an equivalent map of compiled code objects. |
| 453 ParseLogResult new_result; |
| 454 ParseLog(new_log_start, new_log_start + new_log_size, &new_result); |
| 455 |
| 456 // Test their actual equivalence. |
| 457 bool results_equal = true; |
| 458 int ref_idx = -1, new_idx = -1, ref_inc = 1, new_inc = 1; |
| 459 while (ref_inc > 0 || new_inc > 0) { |
| 460 const Address ref_addr = ref_result.min_addr + ref_idx; |
| 461 const Address new_addr = new_result.min_addr + new_idx; |
| 462 ref_inc = ref_addr <= ref_result.max_addr && ref_addr <= new_addr ? 1 : 0; |
| 463 new_inc = new_addr <= new_result.max_addr && new_addr <= ref_addr ? 1 : 0; |
| 464 const int ref_item = ref_result.entities_map[ref_idx]; |
| 465 const int new_item = new_result.entities_map[new_idx]; |
| 466 if (ref_item != -1 || new_item != -1) { |
| 467 CodeEntityInfo ref_entity = |
| 468 ref_item != -1 ? ref_result.entities[ref_item] : NULL; |
| 469 CodeEntityInfo new_entity = |
| 470 new_item != -1 ? new_result.entities[new_item] : NULL; |
| 471 const bool equal = AreEntitiesEqual(ref_entity, new_entity); |
| 472 if (!equal) results_equal = false; |
| 473 PrintCodeEntitiesInfo( |
| 474 equal, ref_inc != 0 ? ref_addr : new_addr, |
| 475 ref_entity, new_entity); |
| 476 } |
| 477 ref_idx += ref_inc; |
| 478 new_idx += new_inc; |
| 479 } |
| 480 CHECK(results_equal); |
| 481 |
| 482 env->Exit(); |
| 483 v8::V8::Dispose(); |
| 484 i::FLAG_always_compact = saved_always_compact; |
| 485 } |
| 486 |
| 487 |
117 #endif // ENABLE_LOGGING_AND_PROFILING | 488 #endif // ENABLE_LOGGING_AND_PROFILING |
OLD | NEW |