tracing-core tests fail on nightly with codegen-units=1 opt-level>0, probably due to LLVM 17

[durin42]

Code

The tracing-core crate, versions 0.1.30 and 0.1.31 (as well as git 941b1591) fails tests:

RUSTFLAGS='-Ccodegen-units=1 -Copt-level=1' cargo +nightly test gives test field::test::value_sets_with_fields_from_other_callsites_are_empty ... FAILED

Version it worked on

Works in beta, and worked in nightly as of ~a week ago. I think the difference is the LLVM 17 upgrade. We've been chasing this defect for a couple weeks inside Google, where we run Rust and LLVM HEAD, and it showed up for us when we started doing more in opt-level=1.

Version with regression

rustc --version --verbose:

rustc 1.73.0-nightly (08d00b40a 2023-08-09)
binary: rustc
commit-hash: 08d00b40aef2017fe6dba3ff7d6476efa0c10888
commit-date: 2023-08-09
host: x86_64-unknown-linux-gnu
release: 1.73.0-nightly
LLVM version: 17.0.0

@rustbot modify labels: +regression-from-stable-to-nightly -regression-untriaged +A-LLVM

[durin42]

Bisecting locally, I think the cause is llvm/llvm-project@336d728

[durin42]

Confirmed that at llvm/llvm-project@487ab39 with llvm/llvm-project@336d728 backed out everything works, that 336d728 change is definitely what triggered this.

[apiraino]

thanks for bisecting this @durin42!

Stacktrace of the failing test

$ RUST_BACKTRACE=full RUSTFLAGS='-Ccodegen-units=1 -Copt-level=1' cargo +nightly test -p tracing-core --lib
test callsite::tests::linked_list_repeated - should panic ... thread 'callsite::tests::linked_list_repeated' panicked at tracing-core/src/callsite.rs:438:13:
assertion failed: `(left != right)`
  left: `0x5649efc1d0e8`,
 right: `0x5649efc1d0e8`: Attempted to register a `Callsite` that already exists! This will cause an infinite loop when attempting to read from the callsite cache. This is likely a bug! You should only need to call `tracing-core::callsite::register` once per `Callsite`.
stack backtrace:
   0:     0x5649efbb675c - std::backtrace_rs::backtrace::libunwind::trace::hbd7dbe1611fe4748
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:     0x5649efbb675c - std::backtrace_rs::backtrace::trace_unsynchronized::hed183926d0ec3d28
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x5649efbb675c - std::sys_common::backtrace::_print_fmt::h587cc5a26dfcd1a1
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/sys_common/backtrace.rs:67:5
   3:     0x5649efbb675c - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hea09c12237a5a482
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/sys_common/backtrace.rs:44:22
   4:     0x5649efbe04dc - core::fmt::rt::Argument::fmt::hb4f5e202a62bea46
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/core/src/fmt/rt.rs:138:9
   5:     0x5649efbe04dc - core::fmt::write::heba65d7649896adb
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/core/src/fmt/mod.rs:1094:21
   6:     0x5649efbb368e - std::io::Write::write_fmt::h1c76e0280d51b4ab
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/io/mod.rs:1714:15
   7:     0x5649efbb6544 - std::sys_common::backtrace::_print::hfe234326a52d92e1
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/sys_common/backtrace.rs:47:5
   8:     0x5649efbb6544 - std::sys_common::backtrace::print::h42df51640bd52506
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/sys_common/backtrace.rs:34:9
   9:     0x5649efbb851a - std::panicking::panic_hook_with_disk_dump::{{closure}}::h77a8a3ee1f21400b
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/panicking.rs:278:22
  10:     0x5649efbb8207 - std::panicking::panic_hook_with_disk_dump::h2c945501520f08af
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/panicking.rs:312:9
  11:     0x5649efbb8b1b - std::panicking::default_hook::h994e39dd0867a71e
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/panicking.rs:239:5
  12:     0x5649efbb8b1b - std::panicking::rust_panic_with_hook::ha9a48e7b8e896118
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/panicking.rs:729:13
  13:     0x5649efbb8a17 - std::panicking::begin_panic_handler::{{closure}}::h06902d78b4993dac
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/panicking.rs:621:13
  14:     0x5649efbb6c86 - std::sys_common::backtrace::__rust_end_short_backtrace::h25b1b17e5cd6256b
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/sys_common/backtrace.rs:170:18
  15:     0x5649efbb8762 - rust_begin_unwind
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/panicking.rs:617:5
  16:     0x5649efb4c7b3 - core::panicking::panic_fmt::hf3068e6facc908ae
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/core/src/panicking.rs:67:14
  17:     0x5649efb4caf5 - core::panicking::assert_failed_inner::h686086dc9c0e5eec
  18:     0x5649efb4813f - core::panicking::assert_failed::ha6f0b85099b5fb34
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/core/src/panicking.rs:229:5
  19:     0x5649efb4dc75 - tracing_core::callsite::LinkedList::push::hd5c5ff6dc6c8546c
                               at /home/$USER/tmp/tracing/tracing-core/src/callsite.rs:438:13
  20:     0x5649efb4dc75 - tracing_core::callsite::tests::linked_list_repeated::hc0d41baace279036
  21:     0x5649efb4dc75 - tracing_core::callsite::tests::linked_list_repeated::{{closure}}::h36042ad02289d349
                               at /home/$USER/tmp/tracing/tracing-core/src/callsite.rs:565:31
  22:     0x5649efb4dc75 - core::ops::function::FnOnce::call_once::h122e4b626242a91b
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/core/src/ops/function.rs:250:5
  23:     0x5649efb8bc1f - core::ops::function::FnOnce::call_once::h47e06cecfcbb9668
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/core/src/ops/function.rs:250:5
  24:     0x5649efb8bc1f - test::__rust_begin_short_backtrace::hafc0aceee23587f1
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/test/src/lib.rs:626:18
  25:     0x5649efb8abde - test::run_test_in_process::{{closure}}::hdc2dd9d36ed71131
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/test/src/lib.rs:649:60
  26:     0x5649efb8abde - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h033a0309064e058b
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/core/src/panic/unwind_safe.rs:271:9
  27:     0x5649efb8abde - std::panicking::try::do_call::hac19019d4e2cc0d0
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/panicking.rs:524:40
  28:     0x5649efb8abde - std::panicking::try::hdcd9f5a42446e745
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/panicking.rs:488:19
  29:     0x5649efb8abde - std::panic::catch_unwind::h72c82d861e3e7e4e
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/panic.rs:142:14
  30:     0x5649efb8abde - test::run_test_in_process::he980b0abd8bc5e5e
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/test/src/lib.rs:649:27
  31:     0x5649efb8abde - test::run_test::{{closure}}::h82f615a0265733d5
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/test/src/lib.rs:572:43
  32:     0x5649efb525a3 - test::run_test::{{closure}}::hbd221c471a3b87b5
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/test/src/lib.rs:600:41
  33:     0x5649efb525a3 - std::sys_common::backtrace::__rust_begin_short_backtrace::hb42f0c1476d4a91e
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/sys_common/backtrace.rs:154:18
  34:     0x5649efb581bb - std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}::hc0f4913655894fdb
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/thread/mod.rs:529:17
  35:     0x5649efb581bb - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h74d789da2873c9ed
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/core/src/panic/unwind_safe.rs:271:9
  36:     0x5649efb581bb - std::panicking::try::do_call::hf974c36101e5daa6
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/panicking.rs:524:40
  37:     0x5649efb581bb - std::panicking::try::h299fec5779298fae
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/panicking.rs:488:19
  38:     0x5649efb581bb - std::panic::catch_unwind::h5284ca28e485087a
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/panic.rs:142:14
  39:     0x5649efb581bb - std::thread::Builder::spawn_unchecked_::{{closure}}::hd54f5fd46707bc5e
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/thread/mod.rs:528:30
  40:     0x5649efb581bb - core::ops::function::FnOnce::call_once{{vtable.shim}}::hfb6ce4419550da1b
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/core/src/ops/function.rs:250:5
  41:     0x5649efbbd215 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h21f20ba95645e1f7
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/alloc/src/boxed.rs:2007:9
  42:     0x5649efbbd215 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h8b5c496bde96de4e
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/alloc/src/boxed.rs:2007:9
  43:     0x5649efbbd215 - std::sys::unix::thread::Thread::new::thread_start::hdd742dfc1bff09d1
                               at /rustc/08d00b40aef2017fe6dba3ff7d6476efa0c10888/library/std/src/sys/unix/thread.rs:108:17
  44:     0x7f2bc67413ec - <unknown>
  45:     0x7f2bc67c1a1c - <unknown>
  46:                0x0 - <unknown>

WG-prioritization assigning priority (Zulip discussion).

Ideally we'd like a small reproducible

@rustbot label -I-prioritize +P-critical +T-compiler +E-needs-mcve

cc: @nikic

[nikic]

On LLVM 17 this compiles down to an address comparison between TEST_CALLSITE_1 and TEST_CALLSITE_2, which get allocated at the same address.

Are ZST statics supposed to have distinct addresses?

[nikic]

Are ZST statics supposed to have distinct addresses?

Okay, pretty sure the answer to that is "no". As such, I think this test was just passing by luck previously.

The test passes for me if I modify it like this to give the callsites distinct addresses:

diff --git a/tracing-core/src/field.rs b/tracing-core/src/field.rs
index 80ca065b..3dc40738 100644
--- a/tracing-core/src/field.rs
+++ b/tracing-core/src/field.rs
@@ -978,8 +978,8 @@ mod test {
     use super::*;
     use crate::metadata::{Kind, Level, Metadata};
 
-    struct TestCallsite1;
-    static TEST_CALLSITE_1: TestCallsite1 = TestCallsite1;
+    struct TestCallsite1(u8);
+    static TEST_CALLSITE_1: TestCallsite1 = TestCallsite1(0);
     static TEST_META_1: Metadata<'static> = metadata! {
         name: "field_test1",
         target: module_path!(),
@@ -999,8 +999,8 @@ mod test {
         }
     }
 
-    struct TestCallsite2;
-    static TEST_CALLSITE_2: TestCallsite2 = TestCallsite2;
+    struct TestCallsite2(u8);
+    static TEST_CALLSITE_2: TestCallsite2 = TestCallsite2(0);
     static TEST_META_2: Metadata<'static> = metadata! {
         name: "field_test2",
         target: module_path!(),

[nikic]

I submitted tokio-rs/tracing#2681 to fix the test, assuming my analysis here is correct.

[durin42]

I wasn't sure initially, but looking at it the PartialEq impl for Identifier is relying on core::ptr::eq and so I agree that the code was working merely by good fortune. I wonder if we should strengthen the warning in the docs for core::ptr::eq to make it clear that ZSTs can behave in unexpected ways.

[DianQK]

I'm not sure if this comment should go in core::ptr::eq. But I agree that we should have a similar one. I also recently found an application at DioxusLabs/dioxus#1112 that relies on distinct addresses. This example assumes that fn has a distinct address.
Perhaps the core library could provide a way to generate distinct address/id.

[nikic]

Going to close this issue, as the problem is not on the rustc/LLVM side.