Long delay before exiting after reporting compilation errors in rustc 1.14.0 nightly when RUST_BACKTRACE=1

[jchlapinski]

When I have any compilation error(s) there is a rather long delay (around 14s on my machine) before rustc finally exits. Successful compilation is very fast.
I am on Ubuntu 16.04 in VMware Workstation 12.5 for Windows virtual machine.

Steps to reproduce:

$ touch test.rs
$ time rustc test.rs
error: main function not found

error: aborting due to previous error


real    0m13.423s
user    0m13.276s
sys 0m0.112s

Meta

rustc --version --verbose:

rustc 1.14.0-nightly (3f4408347 2016-10-27)
binary: rustc
commit-hash: 3f4408347d2109803edbf53c89c8bce575de4b67
commit-date: 2016-10-27
host: x86_64-unknown-linux-gnu
release: 1.14.0-nightly
LLVM version: 3.9

[jchlapinski]

If it helps, that same version of rustc on Windows 10 works OK for me, there is no noticeable delay after compilation error reporting.

[jchlapinski]

Actually I failed to report that I was using Ubuntu 16.04 virtual machine on VMware Workstation 12 (most recent version) on native Windows 10. I just have tested for this issue on Ubuntu 16.04 on bare metal, and rustc worked fine. The issue seems to be related to virtualization somehow.

$ touch test.rs
$ time rustc test.rs
error: main function not found

error: aborting due to previous error


real    0m0.042s
user    0m0.040s
sys 0m0.000s

[alexcrichton]

Note that the compiler continues after it hits the first error, so the compiler could possibly have been doing real compilation work (looking for more errors), so perhaps that's what's happening here?

[retep998]

Have you considered profiling rustc to see where it is spending most of those 13 seconds?

[jchlapinski]

@retep998 here is what I've gathered from 'perf'

$ touch test.rs
$ perf record rustc test.rs
$ perf report --stdio --header

the results from my Ubuntu 16.04 virtual machine running on VMware Workstation (only few lines from the top for brevity):

# ========
# captured on: Sun Oct 30 21:00:17 2016
# hostname : ubuntu
# os release : 4.4.0-45-generic
# perf version : 4.4.21
# arch : x86_64
# nrcpus online : 8
# nrcpus avail : 8
# cpudesc : Intel(R) Core(TM) i7-6700K CPU @ 4.00GHz
# cpuid : GenuineIntel,6,94,3
# total memory : 16415168 kB
# cmdline : /usr/lib/linux-tools-4.4.0-45/perf record rustc test.rs 
# event : name = cycles, , size = 112, { sample_period, sample_freq } = 4000, sample_type = IP|TID|TIME|PERIOD, disabled = 1, inherit = 1, mmap = 1, comm = 1, freq = 1, enable_on_exec = 1, task = 1, sample_id_all = 1, exclude_guest = 1, mmap2 = 1, comm_exec = 1
# HEADER_CPU_TOPOLOGY info available, use -I to display
# HEADER_NUMA_TOPOLOGY info available, use -I to display
# pmu mappings: cpu = 4, msr = 6, software = 1, tracepoint = 2, breakpoint = 5
# ========
#
#
# Total Lost Samples: 0
#
# Samples: 53K of event 'cycles'
# Event count (approx.): 53214853068
#
# Overhead  Command  Shared Object                  Symbol                                                                                         
# ........  .......  .............................  ...............................................................................................................................................................................................................................
#
    96.65%  rustc    libstd-6eb85298.so             [.] backtrace_alloc                                                                                                                                                                                                            
     1.06%  rustc    libstd-6eb85298.so             [.] swap                                                                                                                                                                                                                       
     0.23%  rustc    libstd-6eb85298.so             [.] backtrace_qsort                                                                                                                                                                                                            
     0.11%  rustc    libstd-6eb85298.so             [.] read_function_entry                                                                                                                                                                                                        
     0.11%  rustc    libstd-6eb85298.so             [.] line_compare                                                                                                                                                                                                               
     0.10%  rustc    libstd-6eb85298.so             [.] read_uleb128                                                                                                                                                                                                               
     0.10%  rustc    libstd-6eb85298.so             [.] elf_symbol_compare                                                                                                                                                                                                         
     0.09%  rustc    rustc                          [.] swap                                                                                                                                                                                                                       
     0.08%  rustc    [unknown]                      [k] 0xffffffff813feb49                                                                                                                                                                                                         
     0.08%  rustc    libstd-6eb85298.so             [.] read_line_program                                                                                                                                                                                                          
     0.07%  rustc    libstd-6eb85298.so             [.] advance             

Clearly the problem is backtrace_alloc function.

I will also put here the results from bare metal for comparison.

[jchlapinski]

results for Ubuntu 16.04 running bare metal:

# ========
# captured on: Sun Oct 30 21:16:37 2016
# hostname : kron
# os release : 4.4.0-45-generic
# perf version : 4.4.21
# arch : x86_64
# nrcpus online : 8
# nrcpus avail : 8
# cpudesc : Intel(R) Core(TM) i7-6700K CPU @ 4.00GHz
# cpuid : GenuineIntel,6,94,3
# total memory : 32863380 kB
# cmdline : /usr/lib/linux-tools-4.4.0-45/perf record rustc test.rs 
# event : name = cycles:pp, , size = 112, { sample_period, sample_freq } = 4000, sample_type = IP|TID|TIME|PERIOD, disabled = 1, inherit = 1, mmap = 1, comm = 1, freq = 1, enable_on_exec = 1, task = 1, precise_ip = 2, sample_id_all = 1, exclude_guest = 1, mmap2 = 1, comm_exe
# HEADER_CPU_TOPOLOGY info available, use -I to display
# HEADER_NUMA_TOPOLOGY info available, use -I to display
# pmu mappings: intel_pt = 7, intel_bts = 6, cpu = 4, msr = 8, software = 1, tracepoint = 2, cstate_core = 9, cstate_pkg = 10, breakpoint = 5
# ========
#
#
# Total Lost Samples: 0
#
# Samples: 149  of event 'cycles:pp'
# Event count (approx.): 159792095
#
# Overhead  Command  Shared Object                  Symbol                                                                                         
# ........  .......  .............................  ...............................................................................................................................................................................................................................
#
    10.85%  rustc    ld-2.23.so                     [.] do_lookup_x                                                                                                                                                                                                                
     7.68%  rustc    librustc_metadata-6eb85298.so  [.] rustc_metadata::decoder::_$LT$impl$u20$rustc_metadata..cstore..MetadataBlob$GT$::load_key_map::hf181e213f9856db2                                                                                                           
     6.81%  rustc    ld-2.23.so                     [.] strcmp                                                                                                                                                                                                                     
     6.54%  rustc    ld-2.23.so                     [.] check_match                                                                                                                                                                                                                
     3.45%  rustc    librustc_metadata-6eb85298.so  [.] _$LT$rustc_metadata..schema..Entry$LT$$u27$tcx$GT$$u20$as$u20$serialize..serialize..Decodable$GT$::decode::h6190a6fb1f040282                                                                                               
     3.35%  rustc    [unknown]                      [k] 0xffffffff813feaf7                                                                                                                                                                                                         
     3.04%  rustc    libstd-6eb85298.so             [.] mallocx                                                                                                                                                                                                                    
     3.03%  rustc    ld-2.23.so                     [.] _dl_check_map_versions                                                                                                                                                                                                     
     2.84%  rustc    libsyntax-6eb85298.so          [.] _$LT$std..collections..hash..map..HashMap$LT$K$C$$u20$V$C$$u20$S$GT$$GT$::get::h92e875ddcaeef5eb                                                                                                                           
     2.74%  rustc    ld-2.23.so                     [.] _dl_relocate_object                                                                                                                                                                                                        
     2.73%  rustc    [unknown]                      [k] 0xffffffff811cbca7    

[jchlapinski]

I have just realized that on my virtual machine I had environment variable RUST_BACKTRACE=1, whereas on my bare-metal I had not. Indeed when setting RUST_BACKTRACE=1 on both machines the results are more or less the same (there is a very long delay before rustc exits). So the problem is not with virtualization after all. Definitely the problem lays in backtrace code somewhere.

I started to notice this issue somewhere around a week ago, as I am updating rust nightly very often (daily).

[jchlapinski]

Possibly duplicate of #29293

[m-n]

1.14 beta exhibits this issue. If it goes stable it will be a significant headache/puzzle for everyone who leaves RUST_BACKTRACE set. cc @nikomatsakis

#37571 seems to be a duplicate issue.

In the same 10/25 nightly that introduced this, the release hello world executable size on x86_64-unknown-linux-gnu grew from ~650k to ~2MB, not sure if that may be related.

[shepmaster]

This is negatively impacting the alternate playground, which always sets RUST_BACKTRACE, and is now present in released 1.14.