Error messages from QNN are turned into verbose level messages

[john-dance]

Describe the issue

error1002.onnx.zip

To reproduce

Run the attached model with the QNN EP. With normal log handling, you get just a single un-helpful error message:

Failed to finalize QNN graph. Error code: 1002 at location qnn_model.cc:167 FinalizeGraphs

However, if you turn on verbose logging, you get to see the real errors:

tcm_migration.cc:2088:ERROR:Operator named q::*InputSlicePad (0x1654900000002) not sufficiently tiled to fit in TCM. Requires 12441600 bytes

graph_prepare.cc:2808:ERROR:Graph prepare TCM Migration action failed

graph_prepare.cc:2868:ERROR:Graph prepare failed during optimization with err: 17, Fatal Optimize

These errors should not be labeled verbose. They need to be in the error category.

Urgency

No response

Platform

Windows

OS Version

Android 14

ONNX Runtime Installation

Built from Source

ONNX Runtime Version or Commit ID

1.21

ONNX Runtime API

Python

Architecture

ARM64

Execution Provider

Other / Unknown

Execution Provider Library Version

QNN

[HectorSVC]

@quic-ashigarg
I think it's because the log is not directly QNN log, it's something from lower level and wrapped inside QNN logs.

[HectorSVC]

Now I remember. The existing code is by design. We don't want to let the backend SDK decide the log level when we redirect SDK logs into ORT logs. ORT only includes SDK logs for reference for more details. For each SDK API call, ORT logs with the information depend on the API return code, ORT make the decision of the log levels.

Imagine that, during the ORT graph partitioning, QNN SDK keeps reporting error with op validation failure. It will flush ORT log with errors if we directly map QNN log level to ORT log level. But it only impacts the graph partitioning. The ops failed to be placed on QNN can still be placed by ORT CPU EP. It's not an error for ORT. The is the scenario we encountered before, and that why we made this decision.

[john-dance]

Good point on the partitioning issue.

However, in this case, we are stuck between a rock and a hard place.

We cannot default to verbose logging because this leads to much slower times for models running with ORT. However, users have no clue how to fix the problem with the generic "Error code: 1002 at location qnn_model.cc:167 FinalizeGraphs."

Is it possible to turn that mechanism off during graphFinalize?

[john-dance]

Here is another example. As a user, they have no clue what to do without something from the error logs that are only shown with verbose:

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] tcm_migration.cc:1879:ERROR:no properties registered for q::Grouped_conv_2d

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] graph_prepare.cc:217:ERROR:could not create op: q::Grouped_conv_2d

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] graph_prepare.cc:220:Op creation failure, op id=0x102f000000c0 (q::Grouped_conv_2d) total_inputs=8

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] graph_prepare.cc:205:  Input 0: id=[0x18fb2000000b6] op=[flat_from_vtcm@fH.FH.] output0=[14ConcreteTensorIN5Tdefs11QuantUint16EE]

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] graph_prepare.cc:205:  Input 1: id=[0x18fb3000000c0] op=[flat_from_vtcm@fH.FH.] output0=[14ConcreteTensorIN5Tdefs11QuantUint16EE]

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] graph_prepare.cc:205:  Input 2: id=[0x206ef000000c0] op=[Const] output0=[14ConcreteTensorIN5Tdefs10QuantInt32EE]

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] graph_prepare.cc:205:  Input 3: id=[0x10039aca31df] op=[Shape] output0=[11TensorShapeILj4EE]

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] graph_prepare.cc:205:  Input 4: id=[0x19] op=[Const] output0=[14ConcreteTensorIN5Tdefs5Int32EE]

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] graph_prepare.cc:205:  Input 5: id=[0xa9] op=[Const] output0=[14ConcreteTensorIN5Tdefs5Int32EE]

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] graph_prepare.cc:205:  Input 6: id=[0x17] op=[Const] output0=[14ConcreteTensorIN5Tdefs5Int32EE]

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] graph_prepare.cc:205:  Input 7: id=[0x206cc000000c0] op=[Const] output0=[14ConcreteTensorIN5Tdefs10PlainFloatEE]

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] graph_prepare.cc:1412:ERROR:Op 0x102f000000c0 preparation failed with err:-1

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] QnnDsp <E> "/model/block_cat/DWconv1/Conv_token_75" generated: could not create op

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] QnnDsp <E> RouterFastRPC graph prepare failed 12

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] QnnDsp <V> SSR not encountered

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] QnnDsp <V> Async property not supported. Skipping register Async context

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] QnnDsp <E> Failed to finalize graph (id: 1) with err 1002

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] QnnDsp <V> Wake up free backend (id: 1)'s thread(s)

[04/Jun/2025:03:02:00 +10:00: profiler/trace] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] QnnDsp <I> QnnGraph_finalize done. status 0x3ea

[04/Jun/2025:03:02:00 +10:00: profiler/error] [job_id: jp20qvqmg] [model.onnx] [onnxruntime] Failed to finalize QNN graph. Error code: 1002 at location qnn_model.cc:167 FinalizeGraphs