llvm dev - Oct 2015 - 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.llvm.org/pipermail/llvm-dev/attachments/20151005/015f4782/attachment.html>

Hi Steve:

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

hth...
don

On Mon, Oct 5, 2015 at 11:17 AM, Stephen Thomas via llvm-dev <
llvm-dev at lists.llvm.org> wrote:
> 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
>
> _______________________________________________
> LLVM Developers mailing list
> llvm-dev at lists.llvm.org
> http://lists.llvm.org/cgi-bin/mailman/listinfo/llvm-dev
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.llvm.org/pipermail/llvm-dev/attachments/20151005/aecb8c5b/attachment.html>

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.

--
Mats

On 5 October 2015 at 17:05, don hinton via llvm-dev <llvm-dev at
lists.llvm.org
> wrote:
> Hi Steve:
>
> llvm::errs() is unbuffered, so that might explain it.  Could you try
> llvm::outs() instead and see if that helps.
>
> hth...
> don
>
> On Mon, Oct 5, 2015 at 11:17 AM, Stephen Thomas via llvm-dev <
> llvm-dev at lists.llvm.org> wrote:
>
>> 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
>>
>> _______________________________________________
>> LLVM Developers mailing list
>> llvm-dev at lists.llvm.org
>> http://lists.llvm.org/cgi-bin/mailman/listinfo/llvm-dev
>>
>>
>
> _______________________________________________
> LLVM Developers mailing list
> llvm-dev at lists.llvm.org
> http://lists.llvm.org/cgi-bin/mailman/listinfo/llvm-dev
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.llvm.org/pipermail/llvm-dev/attachments/20151005/f7deb297/attachment.html>

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.

On Mon, Oct 5, 2015 at 8:17 AM, Stephen Thomas via llvm-dev <
llvm-dev at lists.llvm.org> wrote:
> 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
>
> _______________________________________________
> LLVM Developers mailing list
> llvm-dev at lists.llvm.org
> http://lists.llvm.org/cgi-bin/mailman/listinfo/llvm-dev
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.llvm.org/pipermail/llvm-dev/attachments/20151005/6a986bab/attachment.html>

On Mon, Oct 5, 2015 at 12:36 PM, Reid Kleckner <rnk at google.com> wrote:
> 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


>
> On Mon, Oct 5, 2015 at 8:17 AM, Stephen Thomas via llvm-dev <
> llvm-dev at lists.llvm.org> wrote:
>
>> 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
>>
>> _______________________________________________
>> LLVM Developers mailing list
>> llvm-dev at lists.llvm.org
>> http://lists.llvm.org/cgi-bin/mailman/listinfo/llvm-dev
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.llvm.org/pipermail/llvm-dev/attachments/20151005/39ca36eb/attachment.html>

On Mon, Oct 5, 2015 at 12:05 PM, don hinton <hintonda at gmail.com> wrote:
> 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

>
> hth...
> don
>
> On Mon, Oct 5, 2015 at 11:17 AM, Stephen Thomas via llvm-dev <
> llvm-dev at lists.llvm.org> wrote:
>
>> 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
>>
>> _______________________________________________
>> LLVM Developers mailing list
>> llvm-dev at lists.llvm.org
>> http://lists.llvm.org/cgi-bin/mailman/listinfo/llvm-dev
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.llvm.org/pipermail/llvm-dev/attachments/20151005/18799b42/attachment.html>

On Mon, Oct 5, 2015 at 9:36 AM, Reid Kleckner via llvm-dev <
llvm-dev at lists.llvm.org> wrote:
> 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

>
> On Mon, Oct 5, 2015 at 8:17 AM, Stephen Thomas via llvm-dev <
> llvm-dev at lists.llvm.org> wrote:
>
>> 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
>>
>> _______________________________________________
>> LLVM Developers mailing list
>> llvm-dev at lists.llvm.org
>> http://lists.llvm.org/cgi-bin/mailman/listinfo/llvm-dev
>>
>>
>
> _______________________________________________
> LLVM Developers mailing list
> llvm-dev at lists.llvm.org
> http://lists.llvm.org/cgi-bin/mailman/listinfo/llvm-dev
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.llvm.org/pipermail/llvm-dev/attachments/20151005/e235038b/attachment-0001.html>