[SOLVED] Same compute intensive function running on two different cores resulting in different latency

Issue

#include <pthread.h>
#include <fcntl.h>
#include <unistd.h>

#include <iostream>
#include <chrono>

using namespace std;

static inline void stick_this_thread_to_core(int core_id);
static inline void* incrementLoop(void* arg);

struct BenchmarkData {
    long long iteration_count;
    int core_id;
};

pthread_barrier_t g_barrier;

int main(int argc, char** argv)
{
    if(argc != 3) {
        cout << "Usage: ./a.out <core_id> <core_id>" << endl;
        return EXIT_FAILURE;
    }

    cout << "================================================ STARTING ================================================" << endl;

    int core1 = std::stoi(argv[1]);
    int core2 = std::stoi(argv[2]);

    pthread_barrier_init(&g_barrier, nullptr, 2);

    const long long iteration_count = 100'000'000'000;

    BenchmarkData benchmark_data1{iteration_count, core1};
    BenchmarkData benchmark_data2{iteration_count, core2};

    pthread_t worker1, worker2;
    pthread_create(&worker1, nullptr, incrementLoop, static_cast<void*>(&benchmark_data1));
    cout << "Created worker1" << endl;
    pthread_create(&worker2, nullptr, incrementLoop, static_cast<void*>(&benchmark_data2));
    cout << "Created worker2" << endl;

    pthread_join(worker1, nullptr);
    cout << "Joined worker1" << endl;
    pthread_join(worker2, nullptr);
    cout << "Joined worker2" << endl;

    return EXIT_SUCCESS;
}

static inline void stick_this_thread_to_core(int core_id) {
    int num_cores = sysconf(_SC_NPROCESSORS_ONLN);
    if (core_id < 0 || core_id >= num_cores) {
        cerr << "Core " << core_id << " is out of assignable range.\n";
        return;
    }

    cpu_set_t cpuset;
    CPU_ZERO(&cpuset);
    CPU_SET(core_id, &cpuset);

    pthread_t current_thread = pthread_self();

    int res = pthread_setaffinity_np(current_thread, sizeof(cpu_set_t), &cpuset);

    if(res == 0) {
        cout << "Thread bound to core " << core_id << " successfully." << endl;
    } else {
        cerr << "Error in binding this thread to core " << core_id << '\n';
    }
}

static inline void* incrementLoop(void* arg)
{
    BenchmarkData* arg_ = static_cast<BenchmarkData*>(arg);
    int core_id = arg_->core_id;
    long long iteration_count = arg_->iteration_count;

    stick_this_thread_to_core(core_id);

    cout << "Thread bound to core " << core_id << " will now wait for the barrier." << endl;
    pthread_barrier_wait(&g_barrier);
    cout << "Thread bound to core " << core_id << " is done waiting for the barrier." << endl;

    long long data = 0; 
    long long i;

    cout << "Thread bound to core " << core_id << " will now increment private data " << iteration_count / 1'000'000'000.0 << " billion times." << endl;
    std::chrono::steady_clock::time_point begin = std::chrono::steady_clock::now();
    for(i = 0; i < iteration_count; ++i) {
        ++data;
        __asm__ volatile("": : :"memory");
    }

    std::chrono::steady_clock::time_point end = std::chrono::steady_clock::now();
    unsigned long long elapsed_time = std::chrono::duration_cast<std::chrono::milliseconds>(end - begin).count();

    cout << "Elapsed time: " << elapsed_time << " ms, core: " << core_id << ", iteration_count: " << iteration_count << ", data value: " << data << ", i: " << i << endl;

    return nullptr;
}

My compile command:

g++ main.cpp -Ofast -lpthread

I have a basic microbenchmark code in which I spawning two worker threads from the main thread. I am binding spawned threads to core 0 and 1. Both threads call a function called incrementLoop. In this function, threads will increment a local (private to each thread) 100 billion times in a for loop. Then I am measuring the time spent in the for loop for both threads. However, threads running on two different cores produce wildly different elapsed time results on my Skylake server, but elapsed times were very close on my Cascade Lake server. What could be the reason for this?

Here is the output from Cascade Lake, however since I am not protecting output stream from mutual access, output is a little bit crooked due to race:

Created worker1
Created worker2
Thread bound to core Thread bound to core 0 successfully.
Thread bound to core 10 will now wait for the barrier. successfully.

Thread bound to core 1 will now wait for the barrier.
Thread bound to core 1 is done waiting for the barrier.
Thread bound to core 1 will now increment private data 100 billion times.
Thread bound to core 0 is done waiting for the barrier.
Thread bound to core 0 will now increment private data 100 billion times.
Elapsed time: 20861 ms, core: 1, iteration_count: 100000000000, data value: 100000000000, i: 100000000000
Elapsed time: 20925 ms, core: 0, iteration_count: 100000000000, data value: 100000000000, i: 100000000000
Joined worker1
Joined worker2

Here is the output from Skylake, which confuses me:

================================================ STARTING ================================================
Created worker1
Created worker2
Thread bound to core Thread bound to core 01 successfully. successfully.
Thread bound to core 0 will now wait for the barrier.

Thread bound to core 1 will now wait for the barrier.
Thread bound to core 1 is done waiting for the barrier.
Thread bound to core 1 will now increment private data Thread bound to core 0 is done waiting for the barrier.
Thread bound to core 0 will now increment private data 100100 billion times. billion times.

Elapsed time: 27243 ms, core: 0, iteration_count: 100000000000, data value: 100000000000, i: 100000000000
Joined worker1
Elapsed time: 83536 ms, core: 1, iteration_count: 100000000000, data value: 100000000000, i: 100000000000
Joined worker2

Specs of Skylake:

Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                18
On-line CPU(s) list:   0-17
Thread(s) per core:    1
Core(s) per socket:    18
Socket(s):             1
NUMA node(s):          1
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 85
Model name:            Intel(R) Xeon(R) Gold 6154 CPU @ 3.00GHz
Stepping:              4
CPU MHz:               1796.630
CPU max MHz:           3700.0000
CPU min MHz:           1200.0000
BogoMIPS:              6000.00
Virtualization:        VT-x
L1d cache:             32K
L1i cache:             32K
L2 cache:              1024K
L3 cache:              25344K
NUMA node0 CPU(s):     0-17
Flags:                 fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc art arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch epb cat_l3 cdp_l3 invpcid_single intel_ppin intel_pt ssbd mba ibrs ibpb stibp tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 hle avx2 smep bmi2 erms invpcid rtm cqm mpx rdt_a avx512f avx512dq rdseed adx smap clflushopt clwb avx512cd avx512bw avx512vl xsaveopt xsavec xgetbv1 cqm_llc cqm_occup_llc cqm_mbm_total cqm_mbm_local dtherm ida arat pln pts pku ospke md_clear spec_ctrl intel_stibp flush_l1d

Specs of Cascade Lake:

Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                18
On-line CPU(s) list:   0-17
Thread(s) per core:    1
Core(s) per socket:    18
Socket(s):             1
NUMA node(s):          1
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 85
Model name:            Intel(R) Core(TM) i9-10980XE CPU @ 3.00GHz
Stepping:              7
CPU MHz:               4799.926
CPU max MHz:           4800.0000
CPU min MHz:           1200.0000
BogoMIPS:              6000.00
Virtualization:        VT-x
L1d cache:             32K
L1i cache:             32K
L2 cache:              1024K
L3 cache:              25344K
NUMA node0 CPU(s):     0-17
Flags:                 fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc art arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch epb cat_l3 cdp_l3 invpcid_single intel_pt ssbd mba ibrs ibpb stibp ibrs_enhanced tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 hle avx2 smep bmi2 erms invpcid rtm cqm mpx rdt_a avx512f avx512dq rdseed adx smap clflushopt clwb avx512cd avx512bw avx512vl xsaveopt xsavec xgetbv1 cqm_llc cqm_occup_llc cqm_mbm_total cqm_mbm_local dtherm ida arat pln pts avx512_vnni md_clear spec_ctrl intel_stibp flush_l1d arch_capabilities

Also note that I have isolated cores on both servers:

cat /proc/cmdline for Skylake:

BOOT_IMAGE=/vmlinuz-3.10.0-1160.21.1.el7.x86_64 root=/dev/mapper/centos-root ro crashkernel=auto rd.lvm.lv=centos/root rd.lvm.lv=centos/swap rhgb processor.max_cstate=0 nohz_full=0-15 iommu=off intel_idle.max_cstate=0 isolcpus=0-15 idle=poll nosoftlockup mce=ignore_ce quiet skew_tick=1

cat /proc/cmdline for Cascade Lake:

BOOT_IMAGE=/vmlinuz-3.10.0-1160.45.1.el7.x86_64 root=/dev/mapper/centos-root ro crashkernel=auto spectre_v2=retpoline rd.lvm.lv=centos/root rd.lvm.lv=centos/swap rhgb quiet nosoftlockup mce=ignore_ce intel_idle.max_cstate=0 pcie_aspm=performance ipmi_si.force_kipmi=0 nmi_watchdog=0 hpet=disabled noht processor.max_cstate=0 nohalt isolcpus=2-17 nohz=on nohz_full=2-17 rcu_nocbs=2-17 iommu=off audit=0 idle=poll skew_tick=1 skew_tick=1 skew_tick=1 skew_tick=1

I have run these benchmark multiple times and result is the same or close to each other for every run. There are no other processes running on both servers.

Solution

It turns out that cores 0, 16, 17 were running at much higher frequency on my Skylake server.

Answered By – Aydin Özcan

Answer Checked By – Mary Flores (BugsFixing Volunteer)

Leave a Reply

Your email address will not be published. Required fields are marked *