Re: __ftrace_hash_rec_update FTRACE_WARN_ON.

[Steve Hodgson]

On Thu, Jul 25, 2013 at 8:23 PM, Steven Rostedt <rostedt@xxxxxxxxxxx> wrote:
> On Thu, 2013-07-25 at 14:59 -0400, Steven Rostedt wrote:
>
>> Now that I know what's the problem, it shouldn't be too hard to fix.
>
> It was a bit more involved to fix than I expected. I don't like the fact
> that if you filter on only module functions and remove that module, you
> now remove the filter and it traces all functions. Oh well, that's the
> side effect of removing modules that you are only tracing. If you trace
> something other than the module you filter on, it will on remove the
> functions that belong to the module but keep the other functions.
>
> So, removing the module, is basically the same as doing:
>
>  echo '!:mod:<module>' > set_ftrace_filter
>
> and acts the same, almost. It only affects the filter if the function
> trace is currently active. Otherwise it doesn't remove the functions
> from the filter, as it only removes functions from active filters. This
> is because ftrace is only aware of filters that are activated. I also
> added code (set for a separate patch, but combined for this email) that
> will add a 64 bit ref counter. Every time a module removes functions
> from ftrace, the counter is incremented. If a filter is activated it has
> its ref number checked with the current number. If it is different, then
> it tests all the functions in its filter to see if any should be removed
> (no longer exists).
>
> The reason for the warning, was that we enable the function and it was
> mapped in the filter. When we removed the module, we removed its
> functions from the table that keeps track of functions being traced (low
> level tracking, below filters). But we never cleared the filter. When
> the module was added again, it was put back into the same location,
> where the filter matched the address, but the low level table had the
> function disabled, and the filter said it was enabled. When an update
> was made, this discrepancy appeared and caused issues.
>
> You can try this patch to see if it fixes your issues. There may be some
> fuzz to apply it because I added it on top of my current queue that
> needs to go out for 3.11.

This patch fixes ftrace across module removal/reinsertion on our 3.6.11 kernel.

-- Steve Hodgson

>
> -- Steve
>
> diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
> index 9f15c00..3e6ed8f 100644
> --- a/include/linux/ftrace.h
> +++ b/include/linux/ftrace.h
> @@ -114,6 +114,7 @@ struct ftrace_ops {
>         struct ftrace_hash              *notrace_hash;
>         struct ftrace_hash              *filter_hash;
>         struct mutex                    regex_lock;
> +       u64                             mod_cnt;
>  #endif
>  };
>
> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> index 92d3334..366f524 100644
> --- a/kernel/trace/ftrace.c
> +++ b/kernel/trace/ftrace.c
> @@ -93,6 +93,9 @@ struct ftrace_pid {
>         struct pid *pid;
>  };
>
> +/* Keep track of modules unloading and ops updating filters */
> +static u64 mod_ref_cnt;
> +
>  /*
>   * ftrace_disabled is set when an anomaly is discovered.
>   * ftrace_disabled is much stronger than ftrace_enabled.
> @@ -321,6 +324,18 @@ static void add_ftrace_ops(struct ftrace_ops **list, struct ftrace_ops *ops)
>         rcu_assign_pointer(*list, ops);
>  }
>
> +#ifdef CONFIG_DYNAMIC_FTRACE
> +static void verify_ops(struct ftrace_ops *ops);
> +#else
> +static inline void verify_ops(struct ftrace_ops *ops) { }
> +#endif
> +
> +static void add_main_ftrace_ops(struct ftrace_ops *ops)
> +{
> +       verify_ops(ops);
> +       add_ftrace_ops(&ftrace_ops_list, ops);
> +}
> +
>  static int remove_ftrace_ops(struct ftrace_ops **list, struct ftrace_ops *ops)
>  {
>         struct ftrace_ops **p;
> @@ -352,7 +367,7 @@ static void add_ftrace_list_ops(struct ftrace_ops **list,
>         int first = *list == &ftrace_list_end;
>         add_ftrace_ops(list, ops);
>         if (first)
> -               add_ftrace_ops(&ftrace_ops_list, main_ops);
> +               add_main_ftrace_ops(main_ops);
>  }
>
>  static int remove_ftrace_list_ops(struct ftrace_ops **list,
> @@ -405,7 +420,7 @@ static int __register_ftrace_function(struct ftrace_ops *ops)
>                         return -ENOMEM;
>                 add_ftrace_list_ops(&ftrace_control_list, &control_ops, ops);
>         } else
> -               add_ftrace_ops(&ftrace_ops_list, ops);
> +               add_main_ftrace_ops(ops);
>
>         if (ftrace_enabled)
>                 update_ftrace_function();
> @@ -1351,6 +1366,38 @@ alloc_and_copy_ftrace_hash(int size_bits, struct ftrace_hash *hash)
>         return NULL;
>  }
>
> +static void verify_ops(struct ftrace_ops *ops)
> +{
> +       struct ftrace_hash *hash;
> +       struct hlist_node *tn;
> +       struct ftrace_func_entry *entry;
> +       int size;
> +       int i;
> +
> +       /*
> +        * If a module was removed, we may need to verify
> +        * the filters of this ops.
> +        */
> +       if (ops->mod_cnt == mod_ref_cnt)
> +               return;
> +
> +       /* We only need to verify the filter that may enable ops */
> +       hash = ops->filter_hash;
> +       if (ftrace_hash_empty(hash))
> +               return;
> +
> +       size = 1 << hash->size_bits;
> +       for (i = 0; i < size; i++) {
> +               hlist_for_each_entry_safe(entry, tn, &hash->buckets[i], hlist) {
> +                       if (!ftrace_location(entry->ip))
> +                               free_hash_entry(hash, entry);
> +               }
> +       }
> +
> +       /* This ops is now verified. */
> +       ops->mod_cnt = mod_ref_cnt;
> +}
> +
>  static void
>  ftrace_hash_rec_disable(struct ftrace_ops *ops, int filter_hash);
>  static void
> @@ -4061,6 +4108,66 @@ static int ftrace_process_locs(struct module *mod,
>
>  #ifdef CONFIG_MODULES
>
> +/*
> + * If the filter is cleared, then all functions may end up being
> + * traced. We need to pass that information down to update the
> + * records.
> + */
> +static bool remove_rec_entry(struct ftrace_hash *hash, struct dyn_ftrace *rec)
> +{
> +       struct ftrace_func_entry *entry;
> +
> +       entry = ftrace_lookup_ip(hash, rec->ip);
> +       if (!entry)
> +               return false;
> +
> +       free_hash_entry(hash, entry);
> +
> +       /* If we cleared the hash, then we now trace all functions */
> +       return ftrace_hash_empty(hash);
> +}
> +
> +static void clear_recs(struct ftrace_ops *ops, struct ftrace_page *pg)
> +{
> +       struct dyn_ftrace *rec;
> +       bool update = false;
> +       int i;
> +
> +       /* This ops is registered and is cleared here */
> +       ops->mod_cnt = mod_ref_cnt;
> +
> +       for (i = 0; i < pg->index; i++) {
> +               rec = &pg->records[i];
> +
> +               /* If the filter hash gets cleared, we trace all functions */
> +               if (remove_rec_entry(ops->filter_hash, rec))
> +                       update = true;
> +               remove_rec_entry(ops->notrace_hash, rec);
> +       }
> +
> +       if (update) {
> +               ftrace_hash_rec_enable(ops, 1);
> +               if (ftrace_enabled)
> +                       ftrace_run_update_code(FTRACE_UPDATE_CALLS);
> +       }
> +}
> +
> +static bool ops_has_filter(struct ftrace_ops *ops)
> +{
> +       return !ftrace_hash_empty(ops->filter_hash) ||
> +               !ftrace_hash_empty(ops->notrace_hash);
> +}
> +
> +static void clear_hashes(struct ftrace_page *pg)
> +{
> +       struct ftrace_ops *ops;
> +
> +       for (ops = ftrace_ops_list; ops != &ftrace_list_end; ops = ops->next) {
> +               if ((ops->flags & FTRACE_OPS_FL_ENABLED) && ops_has_filter(ops))
> +                       clear_recs(ops, pg);
> +       }
> +}
> +
>  #define next_to_ftrace_page(p) container_of(p, struct ftrace_page, next)
>
>  void ftrace_release_mod(struct module *mod)
> @@ -4068,6 +4175,7 @@ void ftrace_release_mod(struct module *mod)
>         struct dyn_ftrace *rec;
>         struct ftrace_page **last_pg;
>         struct ftrace_page *pg;
> +       bool update_ref = true;
>         int order;
>
>         mutex_lock(&ftrace_lock);
> @@ -4090,10 +4198,23 @@ void ftrace_release_mod(struct module *mod)
>                         if (WARN_ON(pg == ftrace_pages_start))
>                                 goto out_unlock;
>
> +                       /*
> +                        * A module is removing records from ftrace.
> +                        * Any ops not currently registered need to be
> +                        * verified before they get registered.
> +                        */
> +                       if (update_ref) {
> +                               mod_ref_cnt++;
> +                               update_ref = false;
> +                       }
> +
>                         /* Check if we are deleting the last page */
>                         if (pg == ftrace_pages)
>                                 ftrace_pages = next_to_ftrace_page(last_pg);
>
> +                       /* Make sure no hashes reference this module record */
> +                       clear_hashes(pg);
> +
>                         *last_pg = pg->next;
>                         order = get_count_order(pg->size / ENTRIES_PER_PAGE);
>                         free_pages((unsigned long)pg->records, order);
>
>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/