cpu.online_cpus_count() is different from nproc, after SMT change

[narasimhan-v]

avocado-misc-tests/cpu/ppc64_cpu_test.py

Line 125 in ede9581

op2 = cpu.online_cpus_count() / int(self.key)

[narasimhan-v]

This is the code snippet I used to compare the online cpus given by

1. avocado utils
2. nprocs command

    def core(self):
        """
        Tests the core in ppc64_cpu command.
        """
        op1 = process.system_output(
            "ppc64_cpu --cores-present", shell=True).strip().split()[-1]
        op2 = cpu.online_cpus_count() / int(self.key)
        print "avocado utils: online cpus: %d" % cpu.online_cpus_count()
        print "nproc: online cpus: %s" % process.system_output("nproc", shell=True)
        self.equality_check("Core", op1, op2)

15:28:31 INFO | Testing Core
15:28:31 INFO | Running 'ppc64_cpu --smt=4'
15:28:31 INFO | Command 'ppc64_cpu --smt=4' finished with 0 after 0.0444669723511s
15:28:31 INFO | Running 'ppc64_cpu --info'
15:28:31 DEBUG| [stdout] Core   0:    0*    1*    2*    3*    4     5     6     7  
15:28:31 INFO | Command 'ppc64_cpu --info' finished with 0 after 0.0012469291687s
15:28:31 DEBUG| [stdout] Core   1:    8*    9*   10*   11*   12    13    14    15  
15:28:31 INFO | Running 'ppc64_cpu --smt'
15:28:31 DEBUG| [stdout] SMT=4
15:28:31 INFO | Command 'ppc64_cpu --smt' finished with 0 after 0.00242805480957s
15:28:31 INFO | Testing SMT
15:28:31 INFO | Running 'ppc64_cpu --cores-present'
15:28:31 DEBUG| [stdout] Number of cores present = 2
15:28:31 INFO | Command 'ppc64_cpu --cores-present' finished with 0 after 0.00164008140564s
15:28:31 DEBUG| [stdout] avocado utils: online cpus: 2
15:28:31 DEBUG| [stdout] 

15:28:31 INFO | Running 'nproc'
15:28:31 DEBUG| [stdout] 8
15:28:31 INFO | Command 'nproc' finished with 0 after 0.00152802467346s
15:28:31 DEBUG| [stdout] nproc: online cpus: 8
15:28:31 DEBUG| [stdout]

15:28:31 INFO | Testing Core
15:28:31 INFO | Running 'ppc64_cpu --smt=5'
15:28:32 INFO | Command 'ppc64_cpu --smt=5' finished with 0 after 0.0435988903046s
15:28:32 INFO | Running 'ppc64_cpu --info'
15:28:32 DEBUG| [stdout] Core   0:    0*    1*    2*    3*    4*    5     6     7  
15:28:32 INFO | Command 'ppc64_cpu --info' finished with 0 after 0.00104808807373s
15:28:32 DEBUG| [stdout] Core   1:    8*    9*   10*   11*   12*   13    14    15  
15:28:32 INFO | Running 'ppc64_cpu --smt'
15:28:32 DEBUG| [stdout] SMT=5
15:28:32 INFO | Command 'ppc64_cpu --smt' finished with 0 after 0.00244307518005s
15:28:32 INFO | Testing SMT
15:28:32 INFO | Running 'ppc64_cpu --cores-present'
15:28:32 DEBUG| [stdout] Number of cores present = 2
15:28:32 INFO | Command 'ppc64_cpu --cores-present' finished with 0 after 0.0015549659729s
15:28:32 DEBUG| [stdout] avocado utils: online cpus: 10
15:28:32 DEBUG| [stdout] 

15:28:32 INFO | Running 'nproc'
15:28:32 DEBUG| [stdout] 10
15:28:32 INFO | Command 'nproc' finished with 0 after 0.00137114524841s
15:28:32 DEBUG| [stdout] nproc: online cpus: 10
15:28:32 DEBUG| [stdout]

15:28:32 INFO | Testing Core
15:28:32 INFO | Running 'ppc64_cpu --smt=7'
15:28:32 INFO | Command 'ppc64_cpu --smt=7' finished with 0 after 0.0440709590912s
15:28:32 INFO | Running 'ppc64_cpu --info'
15:28:32 DEBUG| [stdout] Core   0:    0*    1*    2*    3*    4*    5*    6*    7  
15:28:32 INFO | Command 'ppc64_cpu --info' finished with 0 after 0.00106191635132s
15:28:32 DEBUG| [stdout] Core   1:    8*    9*   10*   11*   12*   13*   14*   15  
15:28:32 INFO | Running 'ppc64_cpu --smt'
15:28:32 DEBUG| [stdout] SMT=7
15:28:32 INFO | Command 'ppc64_cpu --smt' finished with 0 after 0.00242686271667s
15:28:32 INFO | Testing SMT
15:28:32 INFO | Running 'ppc64_cpu --cores-present'
15:28:32 DEBUG| [stdout] Number of cores present = 2
15:28:32 INFO | Command 'ppc64_cpu --cores-present' finished with 0 after 0.00155282020569s
15:28:32 DEBUG| [stdout] avocado utils: online cpus: 10
15:28:32 DEBUG| [stdout] 

15:28:32 INFO | Running 'nproc'
15:28:32 DEBUG| [stdout] 14
15:28:32 INFO | Command 'nproc' finished with 0 after 0.00137686729431s
15:28:32 DEBUG| [stdout] nproc: online cpus: 14
15:28:32 DEBUG| [stdout]

15:28:32 INFO | Testing Core
15:28:32 INFO | Running 'ppc64_cpu --smt=8'
15:28:32 INFO | Command 'ppc64_cpu --smt=8' finished with 0 after 0.0434079170227s
15:28:32 INFO | Running 'ppc64_cpu --info'
15:28:32 DEBUG| [stdout] Core   0:    0*    1*    2*    3*    4*    5*    6*    7* 
15:28:32 INFO | Command 'ppc64_cpu --info' finished with 0 after 0.00117087364197s
15:28:32 DEBUG| [stdout] Core   1:    8*    9*   10*   11*   12*   13*   14*   15* 
15:28:32 INFO | Running 'ppc64_cpu --smt'
15:28:32 DEBUG| [stdout] SMT=8
15:28:32 INFO | Command 'ppc64_cpu --smt' finished with 0 after 0.0025999546051s
15:28:32 INFO | Testing SMT
15:28:32 INFO | Running 'ppc64_cpu --cores-present'
15:28:32 DEBUG| [stdout] Number of cores present = 2
15:28:32 INFO | Command 'ppc64_cpu --cores-present' finished with 0 after 0.00156998634338s
15:28:32 DEBUG| [stdout] avocado utils: online cpus: 10
15:28:32 DEBUG| [stdout] 

15:28:32 INFO | Running 'nproc'
15:28:32 DEBUG| [stdout] 16
15:28:32 INFO | Command 'nproc' finished with 0 after 0.00157308578491s
15:28:32 DEBUG| [stdout] nproc: online cpus: 16
15:28:32 DEBUG| [stdout] 

[narasimhan-v]

If I introduce a sleep(1) just after setting SMT, both the values are same.
If no sleep, avocado utility gives wrong result, but nproc gives right result

[narasimhan-v]

If I use this line:
op2 = int(process.system_output("nproc", shell=True)) / int(self.key)
then the test passes without any problems

[harish-24]

It seems that the problem persists in SC_NPROCESSORS_ONLN. We need to identify whether the configuration itself takes time to reflect or the python libraries (os.sysconf, multiprocessing.cpu_count) makes it slower.

From what I have observed, the configuration SC_NPROCESSORS_ONLN updation is slower because even the following way is faster (test passes too) than sysconf way.

op2 = int(process.system_output("grep -c ^processor /proc/cpuinfo", shell=True)) / int(self.key)

[narasimhan-v]

@harish-24 @PraveenPenguin any update on this ?

[harish-24]

@narasimhan-v @PraveenPenguin Following are the time observations for each of the SMT from off through 8.

op2 = os.sysconf('SC_NPROCESSORS_ONLN')
8.70227813721e-05
1.90734863281e-06
2.86102294922e-06
0.000107049942017 failed
2.86102294922e-06 failed
9.29832458496e-05 failed
2.86102294922e-06 failed
2.09808349609e-05 failed

op2 = int(process.system_output("grep -c ^processor /proc/cpuinfo", shell=True)) / int(self.key)
0.00867915153503
0.00769901275635
0.0077531337738
0.00808811187744
0.00829696655273
0.00809288024902
0.00819802284241
0.00859785079956

op2 = int(process.system_output("nproc", shell=True)) / int(self.key)
0.0178158283234
0.00502705574036
0.005126953125
0.00514388084412
0.00517201423645
0.00509190559387
0.00515389442444
0.00514507293701

Clearly reading from sysconf is way slower than the other methods. I believe it has to be a bug either in updation of sysconf variable or the way os reads from sysconf.