On Sun, Sep 1, 2013 at 12:01 PM, Sedat Dilek <sedat.dilek@xxxxxxxxx> wrote:
> On Fri, Aug 30, 2013 at 6:52 PM, Linus Torvalds
> <torvalds@xxxxxxxxxxxxxxxxxxxx> wrote:
>> On Fri, Aug 30, 2013 at 9:37 AM, Sedat Dilek <sedat.dilek@xxxxxxxxx> wrote:
>>>
>>> Where is this a.out file from or how to generate it?
>>
>> Oh, that's just the silly threaded test-binary. I don't know what you
>> called it.
>>
>> As to your config options, yesh, you have some expensive stuff.
>> DEBUG_OBJECTS and DEBUG_MUTEXES in particular tend to cause lots of
>> horrible performance issues. I didn't check if there might be other
>> things..
>>
>
> I tried w/o DEBUG_OBJECTS and DEBUG_MUTEXES and disabled some
> unnecessary debug-options, too (see attached diff).
>
> This is what I get now...
>
> [ TEST-CASE ]
>
> $ ~/src/linux-kernel/linux/tools/perf/perf stat --null --repeat 5
> ./scripts/t_lockref_from-linus
> Total loops: 26480075
> Total loops: 27002388
> Total loops: 25761463
> Total loops: 26877615
> Total loops: 27047644
>
> Performance counter stats for './scripts/t_lockref_from-linus' (5 runs):
>
> 10,008617789 seconds time elapsed
> ( +- 0,07% )
>
>
> Looks like this is now 10x faster: ~2.66Mloops (debug) VS.
> ~26.60Mloops (no-debug).
>
> [ PERF-RECORD ]
>
> $ sudo ~/src/linux-kernel/linux/tools/perf/perf record -e cycles:pp
> ./scripts/t_lockref_from-linus
> Total loops: 26601346
> [ perf record: Woken up 25 times to write data ]
> [ perf record: Captured and wrote 6.100 MB perf.data (~266501 samples) ]
>
> [ PERF-REPORT ]
>
> $ sudo ~/src/linux-kernel/linux/tools/perf/perf report -f
>
> Samples: 159K of event 'cycles:pp', Event count (approx.): 76968896763
> 12,79% t_lockref_from- [kernel.kallsyms] [k] irq_return
> 4,36% t_lockref_from- [kernel.kallsyms] [k] __ticket_spin_lock
> 4,36% t_lockref_from- [kernel.kallsyms] [k] __acct_update_integrals
> 4,07% t_lockref_from- [kernel.kallsyms] [k] user_exit
> 3,12% t_lockref_from- [kernel.kallsyms] [k] local_clock
> 2,83% t_lockref_from- [kernel.kallsyms] [k] lockref_get_or_lock
> 2,73% t_lockref_from- [kernel.kallsyms] [k] kmem_cache_alloc
> 2,62% t_lockref_from- [kernel.kallsyms] [k] __d_lookup_rcu
> 2,53% t_lockref_from- libc-2.15.so [.] __xstat64
> 2,53% t_lockref_from- [kernel.kallsyms] [k] kmem_cache_free
> 2,28% t_lockref_from- [kernel.kallsyms] [k] path_init
> 2,27% t_lockref_from- [kernel.kallsyms] [k] link_path_walk
> 1,86% t_lockref_from- [kernel.kallsyms] [k] user_enter
> 1,85% t_lockref_from- [kernel.kallsyms] [k] rcu_eqs_exit_common.isra.43
> 1,81% t_lockref_from- [kernel.kallsyms] [k] sched_clock_cpu
> 1,79% t_lockref_from- [kernel.kallsyms] [k] rcu_eqs_enter_common.isra.45
> 1,78% t_lockref_from- [kernel.kallsyms] [k] path_lookupat
> 1,67% t_lockref_from- [kernel.kallsyms] [k] native_read_tsc
> 1,63% t_lockref_from- [kernel.kallsyms] [k] cp_new_stat
> 1,61% t_lockref_from- [kernel.kallsyms] [k] lockref_put_or_lock
> 1,53% t_lockref_from- [kernel.kallsyms] [k] account_system_time
> 1,48% t_lockref_from- [kernel.kallsyms] [k] tracesys
> 1,47% t_lockref_from- [kernel.kallsyms] [k] copy_user_generic_unrolled
> 1,46% t_lockref_from- [kernel.kallsyms] [k] syscall_trace_enter
> 1,39% t_lockref_from- [kernel.kallsyms] [k] jiffies_to_timeval
> 1,33% t_lockref_from- [kernel.kallsyms] [k] native_sched_clock
> 1,27% t_lockref_from- [kernel.kallsyms] [k] getname_flags
> 1,27% t_lockref_from- [kernel.kallsyms] [k] lookup_fast
> 1,18% t_lockref_from- [kernel.kallsyms] [k] get_vtime_delta
> 1,05% t_lockref_from- [kernel.kallsyms] [k] syscall_trace_leave
> 1,03% t_lockref_from- [kernel.kallsyms] [k] generic_fillattr
> 1,02% t_lockref_from- [kernel.kallsyms] [k] strncpy_from_user
> 1,00% t_lockref_from- [kernel.kallsyms] [k] user_path_at_empty
> 0,97% t_lockref_from- [kernel.kallsyms] [k] account_user_time
> 0,95% t_lockref_from- [kernel.kallsyms] [k] vfs_fstatat
> 0,95% t_lockref_from- [kernel.kallsyms] [k] system_call_after_swapgs
> 0,92% t_lockref_from- [kernel.kallsyms] [k] generic_permission
> 0,91% t_lockref_from- [kernel.kallsyms] [k] filename_lookup
> 0,80% t_lockref_from- [kernel.kallsyms] [k] vfs_getattr
> 0,78% t_lockref_from- [kernel.kallsyms] [k] __ticket_spin_unlock
> 0,74% t_lockref_from- [kernel.kallsyms] [k] complete_walk
> 0,70% t_lockref_from- [kernel.kallsyms] [k] vtime_account_user
> 0,68% t_lockref_from- [kernel.kallsyms] [k] d_rcu_to_refcount
> 0,65% t_lockref_from- [kernel.kallsyms] [k] common_perm
> 0,62% t_lockref_from- [kernel.kallsyms] [k] rcu_eqs_enter
> 0,58% t_lockref_from- [kernel.kallsyms] [k] vtime_user_enter
> 0,57% t_lockref_from- [kernel.kallsyms] [k] __inode_permission
> 0,55% t_lockref_from- [kernel.kallsyms] [k] dput
> 0,52% t_lockref_from- [kernel.kallsyms] [k] apparmor_inode_getattr
> 0,52% t_lockref_from- [kernel.kallsyms] [k] SYSC_newstat
> 0,52% t_lockref_from- [kernel.kallsyms] [k] mntget
> 0,49% t_lockref_from- [kernel.kallsyms] [k] cpuacct_account_field
> 0,48% t_lockref_from- [kernel.kallsyms] [k] __vtime_account_system
> 0,46% t_lockref_from- t_lockref_from-linus [.] start_routine
>
> Thanks for all the explanations and hints.
>
> Regards,
> - Sedat -
>
> P.S.: Some words to "perf -f"...
>
> $ sudo ~/src/linux-kernel/linux/tools/perf/perf record -f -e cycles:pp
> ./scripts/t_lockref_from-linus
> [sudo] password for wearefam:
> Error: unknown switch `f'
>
> usage: perf record [<options>] [<command>]
> or: perf record [<options>] -- <command> [<options>]
>
> -e, --event <event> event selector. use 'perf list' to list
> available events
> --filter <filter>
> event filter
> -p, --pid <pid> record events on existing process id
> -t, --tid <tid> record events on existing thread id
> -r, --realtime <n> collect data with this RT SCHED_FIFO priority
> -D, --no-delay collect data without buffering
> -R, --raw-samples collect raw sample records from all opened counters
> -a, --all-cpus system-wide collection from all CPUs
> -C, --cpu <cpu> list of cpus to monitor
> -c, --count <n> event period to sample
> -o, --output <file> output file name
> -i, --no-inherit child tasks do not inherit counters
> -F, --freq <n> profile at this frequency
> -m, --mmap-pages <n> number of mmap data pages
> --group put the counters into a counter group
> -g, --call-graph <mode[,dump_size]>
> do call-graph (stack chain/backtrace)
> recording: [fp] dwarf
> -v, --verbose be more verbose (show counter open errors, etc)
> -q, --quiet don't print any message
> -s, --stat per thread counts
> -d, --data Sample addresses
> -T, --timestamp Sample timestamps
> -P, --period Sample period
> -n, --no-samples don't sample
> -N, --no-buildid-cache
> do not update the buildid cache
> -B, --no-buildid do not collect buildids in perf.data
> -G, --cgroup <name> monitor event in cgroup name only
> -u, --uid <user> user to profile
> -b, --branch-any sample any taken branches
> -j, --branch-filter <branch filter mask>
> branch stack filter modes
> -W, --weight sample by weight (on special events only)
>
> - EOT -
Attached are the results without the patch from Linus.
- Sedat -
$ diff -uprN /boot/config-3.11.0-rc7-3-iniza-small /boot/config-3.11.0-rc7-3-lockref-small
--- /boot/config-3.11.0-rc7-3-iniza-small 2013-09-01 12:17:51.000000000 +0200
+++ /boot/config-3.11.0-rc7-3-lockref-small 2013-09-01 11:23:21.000000000 +0200
@@ -4334,6 +4334,8 @@ CONFIG_GENERIC_PCI_IOMAP=y
CONFIG_GENERIC_IOMAP=y
CONFIG_GENERIC_IO=y
CONFIG_PERCPU_RWSEM=y
+CONFIG_ARCH_USE_CMPXCHG_LOCKREF=y
+CONFIG_CMPXCHG_LOCKREF=y
# CONFIG_CRC_CCITT is not set
CONFIG_CRC16=y
CONFIG_CRC_T10DIF=y
$ cat /proc/version
Linux version 3.11.0-rc7-3-iniza-small (sedat.dilek@xxxxxxxxx@fambox) (gcc version 4.6.3 (Ubuntu/Linaro 4.6.3-1ubuntu5) ) #1 SMP Sun Sep 1 12:17:33 CEST 2013
$ ~/src/linux-kernel/linux/tools/perf/perf stat --null --repeat 5 ./scripts/t_lockref_from-linus
Total loops: 25528348
Total loops: 25924080
Total loops: 25513405
Total loops: 25619812
Total loops: 25634107
Performance counter stats for './scripts/t_lockref_from-linus' (5 runs):
10,002293452 seconds time elapsed ( +- 0,00% )
$ sudo ~/src/linux-kernel/linux/tools/perf/perf record -e cycles:pp ./scripts/t_lockref_from-linus
Total loops: 25251507
[ perf record: Woken up 25 times to write data ]
[ perf record: Captured and wrote 6.108 MB perf.data (~266857 samples) ]
Samples: 159K of event 'cycles:pp', Event count (approx.): 76914824256
12,16% t_lockref_from- [kernel.kallsyms] [k] irq_return
10,74% t_lockref_from- [kernel.kallsyms] [k] __ticket_spin_lock
4,10% t_lockref_from- [kernel.kallsyms] [k] __acct_update_integrals
3,79% t_lockref_from- [kernel.kallsyms] [k] user_exit
2,98% t_lockref_from- [kernel.kallsyms] [k] local_clock
2,56% t_lockref_from- [kernel.kallsyms] [k] __d_lookup_rcu
2,50% t_lockref_from- libc-2.15.so [.] __xstat64
2,47% t_lockref_from- [kernel.kallsyms] [k] kmem_cache_alloc
2,36% t_lockref_from- [kernel.kallsyms] [k] kmem_cache_free
2,36% t_lockref_from- [kernel.kallsyms] [k] link_path_walk
1,82% t_lockref_from- [kernel.kallsyms] [k] tracesys
1,78% t_lockref_from- [kernel.kallsyms] [k] rcu_eqs_enter_common.isra.45
1,76% t_lockref_from- [kernel.kallsyms] [k] rcu_eqs_exit_common.isra.43
1,75% t_lockref_from- [kernel.kallsyms] [k] user_enter
1,68% t_lockref_from- [kernel.kallsyms] [k] path_lookupat
1,68% t_lockref_from- [kernel.kallsyms] [k] sched_clock_cpu
1,53% t_lockref_from- [kernel.kallsyms] [k] native_read_tsc
1,50% t_lockref_from- [kernel.kallsyms] [k] cp_new_stat
1,49% t_lockref_from- [kernel.kallsyms] [k] dput
1,43% t_lockref_from- [kernel.kallsyms] [k] copy_user_generic_unrolled
1,39% t_lockref_from- [kernel.kallsyms] [k] path_init
1,39% t_lockref_from- [kernel.kallsyms] [k] account_system_time
1,38% t_lockref_from- [kernel.kallsyms] [k] syscall_trace_enter
1,35% t_lockref_from- [kernel.kallsyms] [k] __ticket_spin_unlock
1,31% t_lockref_from- [kernel.kallsyms] [k] jiffies_to_timeval
1,27% t_lockref_from- [kernel.kallsyms] [k] native_sched_clock
1,24% t_lockref_from- [kernel.kallsyms] [k] lookup_fast
1,24% t_lockref_from- [kernel.kallsyms] [k] complete_walk
1,23% t_lockref_from- [kernel.kallsyms] [k] vfs_getattr
1,17% t_lockref_from- [kernel.kallsyms] [k] getname_flags
1,06% t_lockref_from- [kernel.kallsyms] [k] get_vtime_delta
1,06% t_lockref_from- [kernel.kallsyms] [k] syscall_trace_leave
0,94% t_lockref_from- [kernel.kallsyms] [k] generic_fillattr
0,93% t_lockref_from- [kernel.kallsyms] [k] account_user_time
0,92% t_lockref_from- [kernel.kallsyms] [k] strncpy_from_user
0,91% t_lockref_from- [kernel.kallsyms] [k] user_path_at_empty
0,90% t_lockref_from- [kernel.kallsyms] [k] system_call_after_swapgs
0,88% t_lockref_from- [kernel.kallsyms] [k] filename_lookup
0,77% t_lockref_from- [kernel.kallsyms] [k] apparmor_inode_getattr
0,74% t_lockref_from- [kernel.kallsyms] [k] generic_permission
0,73% t_lockref_from- [kernel.kallsyms] [k] vfs_fstatat
0,69% t_lockref_from- [kernel.kallsyms] [k] _raw_spin_lock
0,67% t_lockref_from- [kernel.kallsyms] [k] __inode_permission
0,65% t_lockref_from- [kernel.kallsyms] [k] vtime_account_user
0,64% t_lockref_from- [kernel.kallsyms] [k] __ticket_spin_is_locked
0,57% t_lockref_from- [kernel.kallsyms] [k] vtime_user_enter
0,56% t_lockref_from- [kernel.kallsyms] [k] common_perm
0,56% t_lockref_from- [kernel.kallsyms] [k] rcu_eqs_enter
0,56% t_lockref_from- [kernel.kallsyms] [k] mntget
0,51% t_lockref_from- [kernel.kallsyms] [k] cpuacct_account_field
0,47% t_lockref_from- [kernel.kallsyms] [k] __vtime_account_system
0,44% t_lockref_from- [kernel.kallsyms] [k] lg_local_lock
0,43% t_lockref_from- t_lockref_from-linus [.] start_routine
0,43% t_lockref_from- [kernel.kallsyms] [k] acct_account_cputime
Press '?' for help on key bindings
-dileks // 01-Sep-2013
