Skip to content

Commit 4998d17

Browse files
wwwindwwwind
authored
Arm backend: Move verbose logging behind debug controls. (pytorch#23235)
Performance measurements for MV3 on emulation layer: - targeted verbose lines: 2180 → 0 - log volume: roughly 89–95% lower - debug-only sequence/module traversal is completely removed from normal Info builds - single-execution median improves 1.32% - repeated execution improves 0.61% cc @digantdesai @freddan80 @per @zingo @oscarandersson8218 @mansnils @Sebastian-Larsson @robell @rascani Signed-off-by: Elena Zhelezina <elena.zhelezina@arm.com>
1 parent 2f78245 commit 4998d17

2 files changed

Lines changed: 46 additions & 33 deletions

File tree

‎backends/arm/runtime/VGFBackend.cpp‎

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -457,7 +457,7 @@ class VGFBackend final : public ::executorch::runtime::BackendInterface {
457457
bool is_available() const override {
458458
auto* self = const_cast<VGFBackend*>(this);
459459
const std::lock_guard<std::mutex> lock(mutex_);
460-
ET_LOG(Info, "Checking VGFBackend is available");
460+
ET_LOG(Debug, "Checking VGFBackend is available");
461461
self->ensure_initialized();
462462
const bool available =
463463
is_initialized_ && vkml_load_extensions(&vk_device) == VK_SUCCESS;
@@ -473,7 +473,7 @@ class VGFBackend final : public ::executorch::runtime::BackendInterface {
473473
ArrayRef<CompileSpec> compile_specs) const override {
474474
auto* self = const_cast<VGFBackend*>(this);
475475
const std::lock_guard<std::mutex> lock(mutex_);
476-
ET_LOG(Info, "Entered VGF init");
476+
ET_LOG(Debug, "Entered VGF init");
477477

478478
#ifdef ET_EVENT_TRACER_ENABLED
479479
EventTracer* event_tracer = context.event_tracer();
@@ -589,7 +589,7 @@ class VGFBackend final : public ::executorch::runtime::BackendInterface {
589589
const size_t input_count = repr->model_input_count;
590590
const size_t output_count = repr->model_output_count;
591591
ET_LOG(
592-
Info,
592+
Debug,
593593
"VGF execute: args=%zu IOs=%zu inputs=%zu outputs=%zu",
594594
args.size(),
595595
repr->IOs.size(),
@@ -640,7 +640,7 @@ class VGFBackend final : public ::executorch::runtime::BackendInterface {
640640
++input_arg_idx) {
641641
const int io_idx = repr->model_input_io_index[input_arg_idx];
642642
if (io_idx < 0) {
643-
ET_LOG(Info, "Skipping eliminated VGF input %zu", input_arg_idx);
643+
ET_LOG(Debug, "Skipping eliminated VGF input %zu", input_arg_idx);
644644
// See test_addmm_vgf_no_quant[beta_only]
645645
// two inputs are eliminated from the graph by the converter
646646
continue;
@@ -661,7 +661,7 @@ class VGFBackend final : public ::executorch::runtime::BackendInterface {
661661
Tensor* tensor = &args[input_arg_idx]->toTensor();
662662
IO* io = &repr->IOs[io_idx];
663663

664-
ET_LOG(Info, "Copy input IO[%d] -> args[%zu]", io_idx, input_arg_idx);
664+
ET_LOG(Debug, "Copy input IO[%d] -> args[%zu]", io_idx, input_arg_idx);
665665
size_t io_size = tensor->nbytes();
666666
if (io_size != io->allocation_size) {
667667
#ifdef ET_EVENT_TRACER_ENABLED
@@ -774,7 +774,7 @@ class VGFBackend final : public ::executorch::runtime::BackendInterface {
774774
Tensor* tensor = &args[output_arg_idx]->toTensor();
775775
IO* io = &repr->IOs[io_idx];
776776

777-
ET_LOG(Info, "Copy output IO[%d] -> args[%zu]", io_idx, output_arg_idx);
777+
ET_LOG(Debug, "Copy output IO[%d] -> args[%zu]", io_idx, output_arg_idx);
778778
size_t io_size = tensor->nbytes();
779779
if (io_size != io->allocation_size) {
780780
#ifdef ET_EVENT_TRACER_ENABLED

‎backends/arm/runtime/VGFSetup.cpp‎

Lines changed: 40 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,8 @@
1212

1313
#include <executorch/backends/arm/runtime/VGFSetup.h>
1414

15+
#include <executorch/runtime/platform/log.h>
16+
1517
#include <cstdlib>
1618
#include <limits>
1719

@@ -464,7 +466,7 @@ static VkDescriptorType resolve_descriptor_type(
464466
return vgflib::ToVkDescriptorType(descriptor_type.value());
465467
}
466468
ET_LOG(
467-
Info,
469+
Debug,
468470
"Resource %u has no explicit descriptor type; assuming VK_DESCRIPTOR_TYPE_TENSOR_ARM",
469471
index);
470472
return VK_DESCRIPTOR_TYPE_TENSOR_ARM;
@@ -1384,6 +1386,15 @@ VkResult transition_image_layout(
13841386
return result;
13851387
}
13861388

1389+
static constexpr bool vgf_debug_logging_enabled() {
1390+
#if ET_LOG_ENABLED
1391+
return static_cast<uint32_t>(executorch::runtime::LogLevel::Debug) >=
1392+
static_cast<uint32_t>(executorch::runtime::LogLevel::ET_MIN_LOG_LEVEL);
1393+
#else
1394+
return false;
1395+
#endif
1396+
}
1397+
13871398
static void debug_print_sequence(
13881399
unique_ptr<vgflib::ModelSequenceTableDecoder>& sequence_decoder) {
13891400
auto module_type_to_string = [](vgflib::ModuleType type) {
@@ -1396,34 +1407,34 @@ static void debug_print_sequence(
13961407
return "UNKNOWN";
13971408
}
13981409
};
1399-
ET_LOG(Info, "VGF Sequences:");
1410+
ET_LOG(Debug, "VGF Sequences:");
14001411
for (int i = 0; i < sequence_decoder->modelSequenceTableSize(); i++) {
14011412
ET_LOG(
1402-
Info,
1413+
Debug,
14031414
" Sequence(%d) '%s':",
14041415
i,
14051416
string(sequence_decoder->getSegmentName(i)).c_str());
14061417
auto dispatch_shape = sequence_decoder->getSegmentDispatchShape(i);
14071418
ET_LOG(
1408-
Info,
1419+
Debug,
14091420
" dispatch shape %d %d %d",
14101421
dispatch_shape[0],
14111422
dispatch_shape[1],
14121423
dispatch_shape[2]);
14131424
ET_LOG(
1414-
Info,
1425+
Debug,
14151426
" segment type %s",
14161427
module_type_to_string(sequence_decoder->getSegmentType(i)));
14171428
ET_LOG(
1418-
Info,
1429+
Debug,
14191430
" module index %d",
14201431
sequence_decoder->getSegmentModuleIndex(i));
14211432
auto input_names = sequence_decoder->getModelSequenceInputNamesHandle();
14221433
ET_LOG(
1423-
Info, " names (%ld):", sequence_decoder->getNamesSize(input_names));
1434+
Debug, " names (%ld):", sequence_decoder->getNamesSize(input_names));
14241435
for (int j = 0; j < sequence_decoder->getNamesSize(input_names); j++) {
14251436
ET_LOG(
1426-
Info,
1437+
Debug,
14271438
" %d: %s",
14281439
j,
14291440
string(sequence_decoder->getName(input_names, j)).c_str());
@@ -1452,18 +1463,18 @@ static void debug_print_modules(
14521463
return "UNKNOWN";
14531464
}
14541465
};
1455-
ET_LOG(Info, "VGF Modules:");
1466+
ET_LOG(Debug, "VGF Modules:");
14561467
for (int i = 0; i < module_decoder->size(); i++) {
14571468
auto name = string(module_decoder->getModuleName(i));
14581469
auto entrypoint = string(module_decoder->getModuleEntryPoint(i));
14591470
auto type = module_decoder->getModuleType(i);
14601471
auto spirv = module_decoder->getModuleCode(i);
1461-
ET_LOG(Info, " Module(%d) '%s':", i, name.c_str());
1462-
ET_LOG(Info, " type %s", module_type_to_string(type));
1463-
ET_LOG(Info, " entrypoint '%s'", entrypoint.c_str());
1464-
ET_LOG(Info, " has spirv %d", module_decoder->hasSPIRV(i));
1472+
ET_LOG(Debug, " Module(%d) '%s':", i, name.c_str());
1473+
ET_LOG(Debug, " type %s", module_type_to_string(type));
1474+
ET_LOG(Debug, " entrypoint '%s'", entrypoint.c_str());
1475+
ET_LOG(Debug, " has spirv %d", module_decoder->hasSPIRV(i));
14651476
ET_LOG(
1466-
Info,
1477+
Debug,
14671478
" code size %lu",
14681479
spirv.size()); // read the .begin() to .end()
14691480
}
@@ -1520,7 +1531,8 @@ bool VgfRepr::process_vgf(
15201531
}
15211532

15221533
// Parse the sequences in the VGF (there can be multiple segments).
1523-
{
1534+
// Do not even walk decoder metadata unless Debug logging is compiled in.
1535+
if constexpr (vgf_debug_logging_enabled()) {
15241536
VGF_PROFILE_SCOPE(event_tracer, "VGF_INIT_DEBUG_PRINT_SEQUENCE");
15251537

15261538
debug_print_sequence(sequence_decoder);
@@ -1532,7 +1544,8 @@ bool VgfRepr::process_vgf(
15321544
}
15331545

15341546
// Extract modules
1535-
{
1547+
// Module names, entry points and SPIR-V metadata are diagnostics only.
1548+
if constexpr (vgf_debug_logging_enabled()) {
15361549
VGF_PROFILE_SCOPE(event_tracer, "VGF_INIT_DEBUG_PRINT_MODULES");
15371550

15381551
debug_print_modules(module_decoder);
@@ -2736,7 +2749,7 @@ bool VgfRepr::process_vgf(
27362749
auto segment_name = string(sequence_decoder->getSegmentName(segment_id));
27372750
auto segment_module = sequence_decoder->getSegmentModuleIndex(segment_id);
27382751
ET_LOG(
2739-
Info,
2752+
Debug,
27402753
"VGF segment '%s' module=%u type=%s dispatch=[%u,%u,%u]",
27412754
segment_name.c_str(),
27422755
segment_module,
@@ -2750,7 +2763,7 @@ bool VgfRepr::process_vgf(
27502763
auto segment_m_entrypoint =
27512764
string(module_decoder->getModuleEntryPoint(segment_module));
27522765
ET_LOG(
2753-
Info,
2766+
Debug,
27542767
"VGF module '%s' entrypoint='%s' type=%s has_spirv=%d",
27552768
segment_m_name.c_str(),
27562769
segment_m_entrypoint.c_str(),
@@ -2765,7 +2778,7 @@ bool VgfRepr::process_vgf(
27652778
}
27662779
auto segment_m_spirv =
27672780
get_module_spirv_code(module_decoder, segment_module);
2768-
ET_LOG(Info, "SPIR-V code size (words) %zu", segment_m_spirv.size());
2781+
ET_LOG(Debug, "SPIR-V code size (words) %zu", segment_m_spirv.size());
27692782

27702783
VkShaderModuleCreateInfo smci{
27712784
.sType = VK_STRUCTURE_TYPE_SHADER_MODULE_CREATE_INFO,
@@ -2988,7 +3001,7 @@ bool VgfRepr::process_vgf(
29883001
auto descriptor_count =
29893002
sequence_decoder->getBindingsSize(descriptor_slots);
29903003
ET_LOG(
2991-
Info,
3004+
Debug,
29923005
"VGF descriptor set %u bindings: %zu",
29933006
d_idx,
29943007
descriptor_count);
@@ -3000,7 +3013,7 @@ bool VgfRepr::process_vgf(
30003013
const auto& binding_info = resource_bindings[mrt_i];
30013014
if (binding_info.descriptor_type == VK_DESCRIPTOR_TYPE_TENSOR_ARM) {
30023015
ET_LOG(
3003-
Info,
3016+
Debug,
30043017
"Updating descriptor: segment=%u set=%u binding=%u mrt=%u type=VK_DESCRIPTOR_TYPE_TENSOR_ARM",
30053018
segment_id,
30063019
d_idx,
@@ -3032,7 +3045,7 @@ bool VgfRepr::process_vgf(
30323045
binding_info.descriptor_type ==
30333046
VK_DESCRIPTOR_TYPE_STORAGE_BUFFER) {
30343047
ET_LOG(
3035-
Info,
3048+
Debug,
30363049
"Updating descriptor: segment=%u set=%u binding=%u mrt=%u type=VK_DESCRIPTOR_TYPE_STORAGE_BUFFER",
30373050
segment_id,
30383051
d_idx,
@@ -3074,7 +3087,7 @@ bool VgfRepr::process_vgf(
30743087
? "VK_DESCRIPTOR_TYPE_SAMPLED_IMAGE"
30753088
: "VK_DESCRIPTOR_TYPE_STORAGE_IMAGE");
30763089
ET_LOG(
3077-
Info,
3090+
Debug,
30783091
"Updating descriptor: segment=%u set=%u binding=%u mrt=%u type=%s image_view=%p sampler=%p",
30793092
segment_id,
30803093
d_idx,
@@ -3440,7 +3453,7 @@ bool VgfRepr::process_vgf(
34403453
segment.neural_statistics_status.clear();
34413454

34423455
ET_LOG(
3443-
Info,
3456+
Debug,
34443457
"Bound neural accelerator statistics memory for segment %d, size=%llu",
34453458
segment.segment_id,
34463459
static_cast<unsigned long long>(
@@ -3597,7 +3610,7 @@ bool VgfRepr::process_vgf(
35973610
model_input_io_index[model_input_idx] = io_idx;
35983611

35993612
ET_LOG(
3600-
Info,
3613+
Debug,
36013614
"VGF input: binding_slot=%zu model_input=%zu binding=%u "
36023615
"mrt=%u -> IO[%d]",
36033616
binding_pos,
@@ -3643,7 +3656,7 @@ bool VgfRepr::process_vgf(
36433656
model_output_io_index[output_idx] = io_idx;
36443657

36453658
ET_LOG(
3646-
Info,
3659+
Debug,
36473660
"VGF output: output=%zu binding=%u mrt=%u -> IO[%d]",
36483661
output_idx,
36493662
binding,
@@ -4042,7 +4055,7 @@ bool VgfRepr::process_vgf(
40424055
}
40434056

40444057
bool VgfRepr::execute_vgf(executorch::runtime::EventTracer* event_tracer) {
4045-
ET_LOG(Info, "Executing vgf");
4058+
ET_LOG(Debug, "Executing vgf");
40464059

40474060
VkSubmitInfo submit{
40484061
.sType = VK_STRUCTURE_TYPE_SUBMIT_INFO,

0 commit comments

Comments
 (0)