Why is printing an Instruction so slow?

Hi all,

When writing my custom passes, I often emit log messages to llvm::errs() like so:

llvm::errs() << "Could not handle instruction: " << *Inst << std::endl;

where Inst is a pointer to an Instruction.

I’ve profiled my code and found that this way of printing an Instruction takes a very long time: indeed, it is the bottleneck of my pass.

Of course, I could always switch these log messages off for production runs, but during development and debugging, I’d like to have them on to make debugging much easier.

Is there a faster way to print an Instruction?

Thanks,
Steve

Hi Steve:

llvm::errs() is unbuffered, so that might explain it. Could you try llvm::outs() instead and see if that helps.

hth…
don

Using llvm::outs() will only be noticeably faster if std::endl; is replaced with '\n' or similar, since std::endl; will cause a flush as well - it may be little better, but for buffering to work well, you wan’t a few thousand characters in the buffer, not just a few dozen.

Instruction printing is usually slow because it uses SlotNumbering, which is a whole function analysis to determine what numbers to use for unnamed values.

If printing is part of your critical path, you can use ‘Value::print(raw_ostream&, ModuleSlotTracker&)’ instead of operator<<. I believe it will help you do the analysis once and print many instructions.

Instruction printing is usually slow because it uses SlotNumbering, which
is a whole function analysis to determine what numbers to use for unnamed
values.

If printing is part of your critical path, you can use
'Value::print(raw_ostream&, ModuleSlotTracker&)' instead of operator<<. I
believe it will help you do the analysis once and print many instructions.

Reid,

Thanks for the tip. I don't see a `Value::print()` function with that
signature. I only see `Value::print(raw_ostream&)` (from
http://llvm.org/docs/doxygen/html/classllvm_1_1Value.html). I'm using 3.6.
Is this a 3.7 thing?

Cheers,
Steve

Hi Steve:

llvm::errs() is unbuffered, so that might explain it. Could you try
llvm::outs() instead and see if that helps.

Don,

Nice tip. Switching to llvm::outs() saved about 15% for me. Not a golden
bullet, but still nothing to sneeze at. Printing instructions still remains
the bottleneck for my pass.

I'm curious how llvm-dis is able to write out so much IR text is so little
time.

Thanks,
Steve

Instruction printing is usually slow because it uses SlotNumbering, which
is a whole function analysis to determine what numbers to use for unnamed
values.

If printing is part of your critical path, you can use
'Value::print(raw_ostream&, ModuleSlotTracker&)' instead of operator<<. I
believe it will help you do the analysis once and print many instructions.

It is still linear in the number of types in the module. (I recently tried
to reduce llvm-diff's O((module size)^2) complexity by using
ModuleSlotTracker but it still was quadratic even when using
moduleslottracker)

-- Sean Silva