Re: [PATCH 0/5] [GIT PULL] updates for tip/tracing/ftrace

[Ingo Molnar <mingo@elte.hu>]

ok, with Frederic we figured out the problem.

What helped things most was this trace-dump output:

 0) + 15.281 us   |                }
 0)               |                handle_irq() {
 1) + 35.871 us   |                }
 1)               |                timespec_to_ktime() {
 0)   4.608 us    |                  }
 0)               |                  generic_handle_irq_desc() {
 1)   4.097 us    |                  }
 1) + 14.171 us   |                }
 0)   4.450 us    |                      _spin_lock();
 1) + 60.127 us   |              }
 1)               |              ktime_get() {
 0)               |                      ack_apic_edge() {
 1)               |                  getnstimeofday() {
 0)   6.486 us    |                        }
 0)   5.619 us    |                        irq_complete_move();
 1)   5.158 us    |                      jiffies_read();
 0)               |                        move_native_irq() {
 1) + 15.495 us   |                    }
 1) + 26.161 us   |                  }
 0)   5.631 us    |                          }
 1)   5.549 us    |                  set_normalized_timespec();
 0) + 16.304 us   |                        }
 0)               |                        ack_APIC_irq() {
 1) + 48.377 us   |                }
 1)               |                timespec_to_ktime() {
 0)   5.762 us    |                            native_apic_mem_write();
 1)   5.751 us    |                  }
 0) + 16.162 us   |                          }
 1) + 16.413 us   |                }
 0) + 27.185 us   |                        }
 1) + 81.519 us   |              }
 0) + 80.245 us   |                      }
 1) ! 154.606 us  |            }
 0)               |                      _spin_unlock() {
 1)   5.743 us    |            tick_nohz_update_jiffies();
 0)   5.781 us    |                        }
 1) ! 183.912 us  |          }
 0)   5.327 us    |                        preempt_schedule();
 1) ! 202.575 us  |        }
 0) + 25.827 us   |                      }

 [...]
 1) ! 2623.297 us |  }

i.e. all CPUs spend 2-3 milliseconds to handle a single tick. This 
is on a Core2 Extreme Edition 2.93 GHz CPU, so this kind of cost was 
unexpected.

Until i saw this:

 CONFIG_TRACE_BRANCH_PROFILING=y
 CONFIG_PROFILE_ALL_BRANCHES=y

that explains it all. The above sequence is two CPUs 'lock stepped' 
in a very high overhead series of cacheline ping-pongs. The 
ping-pongs happen due to every branch in the kernel doing:

                ______f.miss_hit[______r]++;

where the branch info metadata is defined as global variables:

                static struct ftrace_branch_data                        \
                        __attribute__((__aligned__(4)))                 \
                        __attribute__((section("_ftrace_branch")))      \

not only is it global, it's also false cacheline-shared due to a 4 
byte alignment.

The proper solution would be to use percpu data and percpu_add() 
primitives for this.

Anyway ... i turned off the branch tracer for my tests.

	Ingo