AuroraMiddleware/v8
1
0
Fork 0
Code Issues 2 Pull Requests Releases Wiki Activity

Introduce Logger::LogCompiledFunctions that logs current map of compiled code.

Browse Source 
The goal is to make possible having --prof flag always enabled in Chromium.  Currently we can't do this because --prof causes compiler and gc to log code creations / moves / deletes which aren't needed until we start profiling.  With LogCompiledFunctions it will be possible not to log anything until we start profiling.  When started, the current map of compiled functions will be logged and compiler / gc logging will be enabled to update current state.  When profling is stopped, logging will be turned off again.

Funny that testing code is actually much longer and complex than function code.

Review URL: http://codereview.chromium.org/112036

git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@2009 ce2b1a6d-e550-0410-aec6-3dcde31c8c00
This commit is contained in:
mikhail.naganov@gmail.com 2009-05-20 09:04:13 +00:00
parent aec2f3d57c
commit 4075179fbe
4 changed files with 444 additions and 7 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
src/compiler.cc
View File

@ -357,8 +357,8 @@ bool Compiler::CompileLazy(Handle<SharedFunctionInfo> shared,
// name and line number. Check explicit whether logging is enabled as finding
// the line number is not for free.
if (Logger::is_enabled() || OProfileAgent::is_enabled()) {
Handle<String> func_name(lit->name()->length() > 0 ?
*lit->name() : shared->inferred_name());
Handle<String> func_name(name->length() > 0 ?
*name : shared->inferred_name());
if (script->name()->IsString()) {
int line_num = GetScriptLineNumber(script, start_position);
if (line_num > 0) {

63
src/log.cc
View File

@ -1108,6 +1108,69 @@ int Logger::GetLogLines(int from_pos, char* dest_buf, int max_size) {
return Log::GetLogLines(from_pos, dest_buf, max_size);
}
void Logger::LogCompiledFunctions() {
HandleScope scope;
Handle<SharedFunctionInfo>* sfis = NULL;
int compiled_funcs_count = 0;
{
AssertNoAllocation no_alloc;
HeapIterator iterator;
while (iterator.has_next()) {
HeapObject* obj = iterator.next();
ASSERT(obj != NULL);
if (obj->IsSharedFunctionInfo()
&& SharedFunctionInfo::cast(obj)->is_compiled()) {
++compiled_funcs_count;
}
}
sfis = NewArray< Handle<SharedFunctionInfo> >(compiled_funcs_count);
iterator.reset();
int i = 0;
while (iterator.has_next()) {
HeapObject* obj = iterator.next();
ASSERT(obj != NULL);
if (obj->IsSharedFunctionInfo()
&& SharedFunctionInfo::cast(obj)->is_compiled()) {
sfis[i++] = Handle<SharedFunctionInfo>(SharedFunctionInfo::cast(obj));
}
}
}
// During iteration, there can be heap allocation due to
// GetScriptLineNumber call.
for (int i = 0; i < compiled_funcs_count; ++i) {
Handle<SharedFunctionInfo> shared = sfis[i];
Handle<String> name(String::cast(shared->name()));
Handle<String> func_name(name->length() > 0 ?
*name : shared->inferred_name());
if (shared->script()->IsScript()) {
Handle<Script> script(Script::cast(shared->script()));
if (script->name()->IsString()) {
Handle<String> script_name(String::cast(script->name()));
int line_num = GetScriptLineNumber(script, shared->start_position());
if (line_num > 0) {
line_num += script->line_offset()->value() + 1;
LOG(CodeCreateEvent("LazyCompile", shared->code(), *func_name,
*script_name, line_num));
} else {
// Can't distinguish enum and script here, so always use Script.
LOG(CodeCreateEvent("Script", shared->code(), *script_name));
}
continue;
}
}
// If no script or script has no name.
LOG(CodeCreateEvent("LazyCompile", shared->code(), *func_name));
}
DeleteArray(sfis);
}
#endif

3
src/log.h
View File

@ -214,6 +214,9 @@ class Logger {
// retrieve previously written messages. See v8.h.
static int GetLogLines(int from_pos, char* dest_buf, int max_size);
// Logs all compiled functions found in the heap.
static void LogCompiledFunctions();
private:
// Emits the source code of a regexp. Used by regexp events.

381
test/cctest/test-log.cc
View File

@ -7,15 +7,17 @@
#include "v8.h"
#include "log.h"
#include "cctest.h"
using v8::internal::Address;
using v8::internal::Logger;
namespace i = v8::internal;
static void SetUp() {
// Log to memory buffer.
v8::internal::FLAG_logfile = "*";
v8::internal::FLAG_log = true;
i::FLAG_logfile = "*";
i::FLAG_log = true;
Logger::Setup();
}
@ -103,8 +105,8 @@ TEST(BeyondWritePosition) {
TEST(MemoryLoggingTurnedOff) {
// Log to stdout
v8::internal::FLAG_logfile = "-";
v8::internal::FLAG_log = true;
i::FLAG_logfile = "-";
i::FLAG_log = true;
Logger::Setup();
CHECK_EQ(0, Logger::GetLogLines(0, NULL, 0));
CHECK_EQ(0, Logger::GetLogLines(100, NULL, 0));
@ -114,4 +116,373 @@ TEST(MemoryLoggingTurnedOff) {
}
static inline bool IsStringEqualTo(const char* r, const char* s) {
return strncmp(r, s, strlen(r)) == 0;
}
static bool Consume(const char* str, char** buf) {
if (IsStringEqualTo(str, *buf)) {
*buf += strlen(str);
return true;
}
return false;
}
static void ParseAddress(char* start, Address* min_addr, Address* max_addr) {
Address addr = reinterpret_cast<Address>(strtoll(start, NULL, 16));
if (addr < *min_addr) *min_addr = addr;
if (addr > *max_addr) *max_addr = addr;
}
static Address ConsumeAddress(
char** start, Address min_addr, Address max_addr) {
char* end_ptr;
Address addr = reinterpret_cast<Address>(strtoll(*start, &end_ptr, 16));
CHECK_GE(addr, min_addr);
CHECK_GE(max_addr, addr);
*start = end_ptr;
return addr;
}
namespace {
// A code entity is a pointer to a position of code-creation event in buffer log
// offset to a point where entity size begins, i.e.: '255,"func"\n'. This makes
// comparing code entities pretty easy.
typedef char* CodeEntityInfo;
// A structure used to return log parsing results.
class ParseLogResult {
public:
ParseLogResult()
: min_addr(reinterpret_cast<Address>(-1)),
max_addr(reinterpret_cast<Address>(0)),
entities_map(NULL), entities(NULL),
max_entities(0) {};
~ParseLogResult() {
// See allocation code below.
if (entities_map != NULL) {
i::DeleteArray(entities_map - 1);
}
i::DeleteArray(entities);
}
void AllocateEntities() {
// Make sure that the test doesn't operate on a bogus log.
CHECK_GT(max_entities, 0);
CHECK_GT(min_addr, 0);
CHECK_GT(max_addr, min_addr);
entities = i::NewArray<CodeEntityInfo>(max_entities);
for (int i = 0; i < max_entities; ++i) {
entities[i] = NULL;
}
// We're adding fake items at [-1] and [size + 1] to simplify
// comparison code.
const int map_length = max_addr - min_addr + 1 + 2; // 2 fakes.
entities_map = i::NewArray<int>(map_length);
for (int i = 0; i < map_length; ++i) {
entities_map[i] = -1;
}
entities_map += 1; // Hide the -1 item, this is compensated on delete.
}
// Minimal code entity address.
Address min_addr;
// Maximal code entity address.
Address max_addr;
// Memory map of entities start addresses. Biased by min_addr.
int* entities_map;
// An array of code entities.
CodeEntityInfo* entities;
// Maximal entities count. Actual entities count can be lower,
// empty entity slots are pointing to NULL.
int max_entities;
};
} // namespace
typedef void (*ParserBlock)(char* start, char* end, ParseLogResult* result);
static void ParserCycle(
char* start, char* end, ParseLogResult* result,
ParserBlock block_creation, ParserBlock block_delete,
ParserBlock block_move) {
const char* code_creation = "code-creation,";
const char* code_delete = "code-delete,";
const char* code_move = "code-move,";
const char* lazy_compile = "LazyCompile,";
const char* script = "Script,";
const char* function = "Function,";
while (start < end) {
if (Consume(code_creation, &start)) {
if (Consume(lazy_compile, &start)
|| Consume(script, &start)
|| Consume(function, &start)) {
block_creation(start, end, result);
}
} else if (Consume(code_delete, &start)) {
block_delete(start, end, result);
} else if (Consume(code_move, &start)) {
block_move(start, end, result);
}
while (start < end && *start != '\n') ++start;
++start;
}
}
static void Pass1CodeCreation(char* start, char* end, ParseLogResult* result) {
ParseAddress(start, &result->min_addr, &result->max_addr);
++result->max_entities;
}
static void Pass1CodeDelete(char* start, char* end, ParseLogResult* result) {
ParseAddress(start, &result->min_addr, &result->max_addr);
}
static void Pass1CodeMove(char* start, char* end, ParseLogResult* result) {
// Skip old address.
while (start < end && *start != ',') ++start;
CHECK_GT(end, start);
++start; // Skip ','.
ParseAddress(start, &result->min_addr, &result->max_addr);
}
static void Pass2CodeCreation(char* start, char* end, ParseLogResult* result) {
Address addr = ConsumeAddress(&start, result->min_addr, result->max_addr);
CHECK_GT(end, start);
++start; // Skip ','.
int idx = addr - result->min_addr;
result->entities_map[idx] = -1;
for (int i = 0; i < result->max_entities; ++i) {
// Find an empty slot and fill it.
if (result->entities[i] == NULL) {
result->entities[i] = start;
result->entities_map[idx] = i;
break;
}
}
// Make sure that a slot was found.
CHECK_GE(result->entities_map[idx], 0);
}
static void Pass2CodeDelete(char* start, char* end, ParseLogResult* result) {
Address addr = ConsumeAddress(&start, result->min_addr, result->max_addr);
int idx = addr - result->min_addr;
// There can be code deletes that are not related to JS code.
if (result->entities_map[idx] >= 0) {
result->entities[result->entities_map[idx]] = NULL;
result->entities_map[idx] = -1;
}
}
static void Pass2CodeMove(char* start, char* end, ParseLogResult* result) {
Address from_addr = ConsumeAddress(
&start, result->min_addr, result->max_addr);
CHECK_GT(end, start);
++start; // Skip ','.
Address to_addr = ConsumeAddress(&start, result->min_addr, result->max_addr);
CHECK_GT(end, start);
int from_idx = from_addr - result->min_addr;
int to_idx = to_addr - result->min_addr;
// There can be code moves that are not related to JS code.
if (from_idx != to_idx && result->entities_map[from_idx] >= 0) {
CHECK_EQ(-1, result->entities_map[to_idx]);
result->entities_map[to_idx] = result->entities_map[from_idx];
result->entities_map[from_idx] = -1;
};
}
static void ParseLog(char* start, char* end, ParseLogResult* result) {
// Pass 1: Calculate boundaries of addresses and entities count.
ParserCycle(start, end, result,
Pass1CodeCreation, Pass1CodeDelete, Pass1CodeMove);
printf("min_addr: %p, max_addr: %p, entities: %d\n",
result->min_addr, result->max_addr, result->max_entities);
result->AllocateEntities();
// Pass 2: Fill in code entries data.
ParserCycle(start, end, result,
Pass2CodeCreation, Pass2CodeDelete, Pass2CodeMove);
}
static inline void PrintCodeEntityInfo(CodeEntityInfo entity) {
const int max_len = 50;
if (entity != NULL) {
char* eol = strchr(entity, '\n');
int len = eol - entity;
len = len <= max_len ? len : max_len;
printf("%-*.*s ", max_len, len, entity);
} else {
printf("%*s", max_len + 1, "");
}
}
static void PrintCodeEntitiesInfo(
bool is_equal, Address addr,
CodeEntityInfo l_entity, CodeEntityInfo r_entity) {
printf("%c %p ", is_equal ? ' ' : '*', addr);
PrintCodeEntityInfo(l_entity);
PrintCodeEntityInfo(r_entity);
printf("\n");
}
static inline int StrChrLen(const char* s, char c) {
return strchr(s, c) - s;
}
static bool AreFuncSizesEqual(CodeEntityInfo ref_s, CodeEntityInfo new_s) {
int ref_len = StrChrLen(ref_s, ',');
int new_len = StrChrLen(new_s, ',');
return ref_len == new_len && strncmp(ref_s, new_s, ref_len) == 0;
}
static bool AreFuncNamesEqual(CodeEntityInfo ref_s, CodeEntityInfo new_s) {
// Skip size.
ref_s = strchr(ref_s, ',') + 1;
new_s = strchr(new_s, ',') + 1;
int ref_len = StrChrLen(ref_s, '\n');
int new_len = StrChrLen(new_s, '\n');
// If reference is anonymous (""), it's OK to have anything in new.
if (ref_len == 2) return true;
// A special case for ErrorPrototype. Haven't yet figured out why they
// are different.
const char* error_prototype = "\"ErrorPrototype";
if (IsStringEqualTo(error_prototype, ref_s)
&& IsStringEqualTo(error_prototype, new_s)) {
return true;
}
return ref_len == new_len && strncmp(ref_s, new_s, ref_len) == 0;
}
static bool AreEntitiesEqual(CodeEntityInfo ref_e, CodeEntityInfo new_e) {
if (ref_e == NULL && new_e != NULL) return true;
if (ref_e != NULL && new_e != NULL) {
return AreFuncSizesEqual(ref_e, new_e) && AreFuncNamesEqual(ref_e, new_e);
}
if (ref_e != NULL && new_e == NULL) {
// args_count entities (argument adapters) are not found by heap traversal,
// but they are not needed because they doesn't contain any code.
ref_e = strchr(ref_e, ',') + 1;
const char* args_count = "\"args_count:";
return IsStringEqualTo(args_count, ref_e);
}
return false;
}
// Test that logging of code create / move / delete events
// is equivalent to traversal of a resulting heap.
TEST(EquivalenceOfLoggingAndTraversal) {
i::FLAG_logfile = "*";
i::FLAG_log = true;
i::FLAG_log_code = true;
// Make sure objects move.
bool saved_always_compact = i::FLAG_always_compact;
if (!i::FLAG_never_compact) {
i::FLAG_always_compact = true;
}
v8::Persistent<v8::Context> env = v8::Context::New();
v8::HandleScope scope;
env->Enter();
// Compile and run a function that creates other functions.
v8::Script::Compile(v8::String::New(
"(function f() {\n"
" var rets = [];\n"
" for (var i = 0; i < 100; ++i) {\n"
" rets.push((function inc(n) { return n + 1; })(i));\n"
" }\n"
"})();"))->Run();
i::Heap::CollectAllGarbage();
i::EmbeddedVector<char,204800> buffer;
int log_size;
ParseLogResult ref_result;
// Retrieve the log.
{
// Make sure that no GCs occur prior to LogCompiledFunctions call.
i::AssertNoAllocation no_alloc;
log_size = Logger::GetLogLines(0, buffer.start(), buffer.length());
CHECK_GT(log_size, 0);
CHECK_GT(buffer.length(), log_size);
// Fill a map of compiled code objects.
ParseLog(buffer.start(), buffer.start() + log_size, &ref_result);
}
// Iterate heap to find compiled functions, will write to log.
i::Logger::LogCompiledFunctions();
char* new_log_start = buffer.start() + log_size;
const int new_log_size = Logger::GetLogLines(
log_size, new_log_start, buffer.length() - log_size);
CHECK_GT(new_log_size, 0);
CHECK_GT(buffer.length(), log_size + new_log_size);
// Fill an equivalent map of compiled code objects.
ParseLogResult new_result;
ParseLog(new_log_start, new_log_start + new_log_size, &new_result);
// Test their actual equivalence.
bool results_equal = true;
int ref_idx = -1, new_idx = -1, ref_inc = 1, new_inc = 1;
while (ref_inc > 0 || new_inc > 0) {
const Address ref_addr = ref_result.min_addr + ref_idx;
const Address new_addr = new_result.min_addr + new_idx;
ref_inc = ref_addr <= ref_result.max_addr && ref_addr <= new_addr ? 1 : 0;
new_inc = new_addr <= new_result.max_addr && new_addr <= ref_addr ? 1 : 0;
const int ref_item = ref_result.entities_map[ref_idx];
const int new_item = new_result.entities_map[new_idx];
if (ref_item != -1 || new_item != -1) {
CodeEntityInfo ref_entity =
ref_item != -1 ? ref_result.entities[ref_item] : NULL;
CodeEntityInfo new_entity =
new_item != -1 ? new_result.entities[new_item] : NULL;
const bool equal = AreEntitiesEqual(ref_entity, new_entity);
if (!equal) results_equal = false;
PrintCodeEntitiesInfo(
equal, ref_inc != 0 ? ref_addr : new_addr,
ref_entity, new_entity);
}
ref_idx += ref_inc;
new_idx += new_inc;
}
CHECK(results_equal);
env->Exit();
v8::V8::Dispose();
i::FLAG_always_compact = saved_always_compact;
}
#endif // ENABLE_LOGGING_AND_PROFILING