From 0eb98a22c3a1be607fd5deb76273ccf4177aebda Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Maciej=20=C5=BBenczykowski?= Date: Tue, 30 Apr 2024 22:35:08 -0700 Subject: [PATCH] BpfLoader: drastically reduce logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Should speed up boot time - especially if serial console is enabled. There's probably still enough information available to debug issues, as any errors (which basically shouldn't happen) are still all extensively logged. Either way, as this now only loads platform bpf .o files, anyone seeing boot time problems can simply flash a custom build with changes to the platform BpfLoader to enable any extra logging as needed. (Note that AFAICT normally ALOGV() is basically ignored) Test: TreeHugger Signed-off-by: Maciej Żenczykowski Change-Id: I5e404ae14c33ee319c07be42defdc270b15a54fe --- loader/BpfLoader.cpp | 2 +- loader/Loader.cpp | 51 ++++++++++++++++++++++---------------------- 2 files changed, 26 insertions(+), 27 deletions(-) diff --git a/loader/BpfLoader.cpp b/loader/BpfLoader.cpp index e6800e6..9f61ba1 100644 --- a/loader/BpfLoader.cpp +++ b/loader/BpfLoader.cpp @@ -119,7 +119,7 @@ int loadAllElfObjects(const android::bpf::Location& location) { if (critical) retVal = ret; ALOGE("Failed to load object: %s, ret: %s", progPath.c_str(), std::strerror(-ret)); } else { - ALOGI("Loaded object: %s", progPath.c_str()); + ALOGV("Loaded object: %s", progPath.c_str()); } } closedir(dir); diff --git a/loader/Loader.cpp b/loader/Loader.cpp index 746aca8..dd242e2 100644 --- a/loader/Loader.cpp +++ b/loader/Loader.cpp @@ -223,7 +223,7 @@ unsigned int readSectionUint(const char* name, ifstream& elfFile, unsigned int d vector theBytes; int ret = readSectionByName(name, elfFile, theBytes); if (ret) { - ALOGD("Couldn't find section %s (defaulting to %u [0x%x]).", name, defVal, defVal); + ALOGV("Couldn't find section %s (defaulting to %u [0x%x]).", name, defVal, defVal); return defVal; } else if (theBytes.size() < sizeof(unsigned int)) { ALOGE("Section %s too short (defaulting to %u [0x%x]).", name, defVal, defVal); @@ -237,7 +237,7 @@ unsigned int readSectionUint(const char* name, ifstream& elfFile, unsigned int d value += static_cast(theBytes[1]); value <<= 8; value += static_cast(theBytes[0]); - ALOGI("Section %s value is %u [0x%x]", name, value, value); + ALOGV("Section %s value is %u [0x%x]", name, value, value); return value; } } @@ -438,7 +438,7 @@ static int readCodeSections(ifstream& elfFile, vector& cs, ret = readSectionByIdx(elfFile, i, cs_temp.data); if (ret) return ret; - ALOGD("Loaded code section %d (%s)", i, name.c_str()); + ALOGV("Loaded code section %d (%s)", i, name.c_str()); vector csSymNames; ret = getSectionSymNames(elfFile, oldName, csSymNames, STT_FUNC); @@ -458,13 +458,13 @@ static int readCodeSections(ifstream& elfFile, vector& cs, if (name == (".rel" + oldName)) { ret = readSectionByIdx(elfFile, i + 1, cs_temp.rel_data); if (ret) return ret; - ALOGD("Loaded relo section %d (%s)", i, name.c_str()); + ALOGV("Loaded relo section %d (%s)", i, name.c_str()); } } if (cs_temp.data.size() > 0) { cs.push_back(std::move(cs_temp)); - ALOGD("Adding section %d to cs list", i); + ALOGV("Adding section %d to cs list", i); } } return 0; @@ -559,14 +559,14 @@ static int createMaps(const char* elfPath, ifstream& elfFile, vector& if (md[i].zero != 0) abort(); if (kvers < md[i].min_kver) { - ALOGI("skipping map %s which requires kernel version 0x%x >= 0x%x", + ALOGD("skipping map %s which requires kernel version 0x%x >= 0x%x", mapNames[i].c_str(), kvers, md[i].min_kver); mapFds.push_back(unique_fd()); continue; } if (kvers >= md[i].max_kver) { - ALOGI("skipping map %s which requires kernel version 0x%x < 0x%x", + ALOGD("skipping map %s which requires kernel version 0x%x < 0x%x", mapNames[i].c_str(), kvers, md[i].max_kver); mapFds.push_back(unique_fd()); continue; @@ -604,7 +604,7 @@ static int createMaps(const char* elfPath, ifstream& elfFile, vector& if (access(mapPinLoc.c_str(), F_OK) == 0) { fd.reset(mapRetrieveRO(mapPinLoc.c_str())); saved_errno = errno; - ALOGD("bpf_create_map reusing map %s, ret: %d", mapNames[i].c_str(), fd.get()); + ALOGV("bpf_create_map reusing map %s, ret: %d", mapNames[i].c_str(), fd.get()); reuse = true; } else { union bpf_attr req = { @@ -617,7 +617,7 @@ static int createMaps(const char* elfPath, ifstream& elfFile, vector& strlcpy(req.map_name, mapNames[i].c_str(), sizeof(req.map_name)); fd.reset(bpf(BPF_MAP_CREATE, req)); saved_errno = errno; - ALOGD("bpf_create_map name %s, ret: %d", mapNames[i].c_str(), fd.get()); + ALOGV("bpf_create_map name %s, ret: %d", mapNames[i].c_str(), fd.get()); } if (!fd.ok()) return -saved_errno; @@ -654,7 +654,7 @@ static int createMaps(const char* elfPath, ifstream& elfFile, vector& if (mapId == -1) { ALOGE("bpfGetFdMapId failed, ret: %d [%d]", mapId, errno); } else { - ALOGI("map %s id %d", mapPinLoc.c_str(), mapId); + ALOGD("map %s id %d", mapPinLoc.c_str(), mapId); } mapFds.push_back(std::move(fd)); @@ -674,7 +674,7 @@ static void applyRelo(void* insnsPtr, Elf64_Addr offset, int fd) { // Occasionally might be useful for relocation debugging, but pretty spammy if (0) { - ALOGD("applying relo to instruction at byte offset: %llu, " + ALOGV("applying relo to instruction at byte offset: %llu, " "insn offset %d, insn %llx", (unsigned long long)offset, insnIndex, *(unsigned long long*)insn); } @@ -739,10 +739,11 @@ static int loadCodeSections(const char* elfPath, vector& cs, const unsigned min_kver = cs[i].prog_def->min_kver; unsigned max_kver = cs[i].prog_def->max_kver; - ALOGD("cs[%d].name:%s min_kver:%x .max_kver:%x (kvers:%x)", i, name.c_str(), min_kver, - max_kver, kvers); - if (kvers < min_kver) continue; - if (kvers >= max_kver) continue; + if (kvers < min_kver || kvers >= max_kver) { + ALOGD("skipping program cs[%d].name:%s min_kver:%x max_kver:%x (kvers:%x)", + i, name.c_str(), min_kver, max_kver, kvers); + continue; + } // strip any potential $foo suffix // this can be used to provide duplicate programs @@ -756,7 +757,7 @@ static int loadCodeSections(const char* elfPath, vector& cs, const objName + '_' + string(name); if (access(progPinLoc.c_str(), F_OK) == 0) { fd.reset(retrieveProgram(progPinLoc.c_str())); - ALOGD("New bpf prog load reusing prog %s, ret: %d (%s)", progPinLoc.c_str(), fd.get(), + ALOGV("New bpf prog load reusing prog %s, ret: %d (%s)", progPinLoc.c_str(), fd.get(), (!fd.ok() ? std::strerror(errno) : "no error")); reuse = true; } else { @@ -776,10 +777,10 @@ static int loadCodeSections(const char* elfPath, vector& cs, const strlcpy(req.prog_name, cs[i].name.c_str(), sizeof(req.prog_name)); fd.reset(bpf(BPF_PROG_LOAD, req)); - ALOGD("BPF_PROG_LOAD call for %s (%s) returned fd: %d (%s)", elfPath, - cs[i].name.c_str(), fd.get(), (!fd.ok() ? std::strerror(errno) : "no error")); - if (!fd.ok()) { + ALOGW("BPF_PROG_LOAD call for %s (%s) returned fd: %d (%s)", elfPath, + cs[i].name.c_str(), fd.get(), std::strerror(errno)); + vector lines = android::base::Split(log_buf.data(), "\n"); ALOGW("BPF_PROG_LOAD - BEGIN log_buf contents:"); @@ -821,7 +822,7 @@ static int loadCodeSections(const char* elfPath, vector& cs, const if (progId == -1) { ALOGE("bpfGetFdProgId failed, ret: %d [%d]", progId, errno); } else { - ALOGI("prog %s id %d", progPinLoc.c_str(), progId); + ALOGD("prog %s id %d", progPinLoc.c_str(), progId); } } @@ -848,13 +849,11 @@ int loadProg(const char* elfPath, bool* isCritical, const Location& location) { if (ret) { ALOGE("Couldn't find license in %s", elfPath); return ret; - } else { - ALOGD("Loading %s%s ELF object %s with license %s", - *isCritical ? "critical for " : "optional", *isCritical ? (char*)critical.data() : "", - elfPath, (char*)license.data()); } - ALOGI("Platform BpfLoader processing ELF object %s", elfPath); + ALOGI("Platform BpfLoader loading %s%s ELF object %s with license %s", + *isCritical ? "critical for " : "optional", *isCritical ? (char*)critical.data() : "", + elfPath, (char*)license.data()); ret = readCodeSections(elfFile, cs, location.allowedProgTypes, location.allowedProgTypesLength); if (ret) { @@ -869,7 +868,7 @@ int loadProg(const char* elfPath, bool* isCritical, const Location& location) { } for (int i = 0; i < (int)mapFds.size(); i++) - ALOGD("map_fd found at %d is %d in %s", i, mapFds[i].get(), elfPath); + ALOGV("map_fd found at %d is %d in %s", i, mapFds[i].get(), elfPath); applyMapRelo(elfFile, mapFds, cs);