Re: [PATCH v2 07/17] debugobjects: Move printk out of db lock critical sections

Waiman Long
2018-11-21T16:50:00Z

On 11/19/2018 01:55 PM, Waiman Long wrote:
> The db->lock is a raw spinlock and so the lock hold time is supposed
> to be short. This will not be the case when printk() is being involved
> in some of the critical sections. In order to avoid the long hold time,
> in case some messages need to be printed, the debug_object_is_on_stack()
> and debug_print_object() calls are now moved out of those critical
> sections.
>
> Signed-off-by: Waiman Long <longman@redhat.com>
> ---
> lib/debugobjects.c | 61 +++++++++++++++++++++++++++++++++++++-----------------
> 1 file changed, 42 insertions(+), 19 deletions(-)
>
> diff --git a/lib/debugobjects.c b/lib/debugobjects.c
> index 403dd95..4216d3d 100644
> --- a/lib/debugobjects.c
> +++ b/lib/debugobjects.c
> @@ -376,6 +376,8 @@ static void debug_object_is_on_stack(void *addr, int onstack)
> struct debug_bucket *db;
> struct debug_obj *obj;
> unsigned long flags;
> + bool debug_printobj = false;
> + bool debug_chkstack = false;
>
> fill_pool();
>
> @@ -392,7 +394,7 @@ static void debug_object_is_on_stack(void *addr, int onstack)
> debug_objects_oom();
> return;
> }
> - debug_object_is_on_stack(addr, onstack);
> + debug_chkstack = true;
> }
>
> switch (obj->state) {
> @@ -403,20 +405,25 @@ static void debug_object_is_on_stack(void *addr, int onstack)
> break;
>
> case ODEBUG_STATE_ACTIVE:
> - debug_print_object(obj, "init");
> state = obj->state;
> raw_spin_unlock_irqrestore(&db->lock, flags);
> + debug_print_object(obj, "init");
> debug_object_fixup(descr->fixup_init, addr, state);
> return;
>
> case ODEBUG_STATE_DESTROYED:
> - debug_print_object(obj, "init");
> + debug_printobj = true;
> break;
> default:
> break;
> }
>
> raw_spin_unlock_irqrestore(&db->lock, flags);
> + if (debug_chkstack)
> + debug_object_is_on_stack(addr, onstack);
> + if (debug_printobj)
> + debug_print_object(obj, "init");
> +
> }
>
> /**
> @@ -474,6 +481,8 @@ int debug_object_activate(void *addr, struct debug_obj_descr *descr)
>
> obj = lookup_object(addr, db);
> if (obj) {
> + bool debug_printobj = false;
> +
> switch (obj->state) {
> case ODEBUG_STATE_INIT:
> case ODEBUG_STATE_INACTIVE:
> @@ -482,14 +491,14 @@ int debug_object_activate(void *addr, struct debug_obj_descr *descr)
> break;
>
> case ODEBUG_STATE_ACTIVE:
> - debug_print_object(obj, "activate");
> state = obj->state;
> raw_spin_unlock_irqrestore(&db->lock, flags);
> + debug_print_object(obj, "activate");
> ret = debug_object_fixup(descr->fixup_activate, addr, state);
> return ret ? 0 : -EINVAL;
>
> case ODEBUG_STATE_DESTROYED:
> - debug_print_object(obj, "activate");
> + debug_printobj = true;
> ret = -EINVAL;
> break;
> default:
> @@ -497,10 +506,13 @@ int debug_object_activate(void *addr, struct debug_obj_descr *descr)
> break;
> }
> raw_spin_unlock_irqrestore(&db->lock, flags);
> + if (debug_printobj)
> + debug_print_object(obj, "activate");
> return ret;
> }
>
> raw_spin_unlock_irqrestore(&db->lock, flags);
> +
> /*
> * We are here when a static object is activated. We
> * let the type specific code confirm whether this is
> @@ -532,6 +544,7 @@ void debug_object_deactivate(void *addr, struct debug_obj_descr *descr)
> struct debug_bucket *db;
> struct debug_obj *obj;
> unsigned long flags;
> + bool debug_printobj = false;
>
> if (!debug_objects_enabled)
> return;
> @@ -549,24 +562,27 @@ void debug_object_deactivate(void *addr, struct debug_obj_descr *descr)
> if (!obj->astate)
> obj->state = ODEBUG_STATE_INACTIVE;
> else
> - debug_print_object(obj, "deactivate");
> + debug_printobj = true;
> break;
>
> case ODEBUG_STATE_DESTROYED:
> - debug_print_object(obj, "deactivate");
> + debug_printobj = true;
> break;
> default:
> break;
> }
> - } else {
> + }
> +
> + raw_spin_unlock_irqrestore(&db->lock, flags);
> + if (!obj) {
> struct debug_obj o = { .object = addr,
> .state = ODEBUG_STATE_NOTAVAILABLE,
> .descr = descr };
>
> debug_print_object(&o, "deactivate");
> + } else if (debug_printobj) {
> + debug_print_object(obj, "deactivate");
> }
> -
> - raw_spin_unlock_irqrestore(&db->lock, flags);
> }
> EXPORT_SYMBOL_GPL(debug_object_deactivate);
>
> @@ -581,6 +597,7 @@ void debug_object_destroy(void *addr, struct debug_obj_descr *descr)
> struct debug_bucket *db;
> struct debug_obj *obj;
> unsigned long flags;
> + bool debug_printobj = false;
>
> if (!debug_objects_enabled)
> return;
> @@ -600,20 +617,22 @@ void debug_object_destroy(void *addr, struct debug_obj_descr *descr)
> obj->state = ODEBUG_STATE_DESTROYED;
> break;
> case ODEBUG_STATE_ACTIVE:
> - debug_print_object(obj, "destroy");
> state = obj->state;
> raw_spin_unlock_irqrestore(&db->lock, flags);
> + debug_print_object(obj, "destroy");
> debug_object_fixup(descr->fixup_destroy, addr, state);
> return;
>
> case ODEBUG_STATE_DESTROYED:
> - debug_print_object(obj, "destroy");
> + debug_printobj = true;
> break;
> default:
> break;
> }
> out_unlock:
> raw_spin_unlock_irqrestore(&db->lock, flags);
> + if (debug_printobj)
> + debug_print_object(obj, "destroy");
> }
> EXPORT_SYMBOL_GPL(debug_object_destroy);
>
> @@ -642,9 +661,9 @@ void debug_object_free(void *addr, struct debug_obj_descr *descr)
>
> switch (obj->state) {
> case ODEBUG_STATE_ACTIVE:
> - debug_print_object(obj, "free");
> state = obj->state;
> raw_spin_unlock_irqrestore(&db->lock, flags);
> + debug_print_object(obj, "free");
> debug_object_fixup(descr->fixup_free, addr, state);
> return;
> default:
> @@ -717,6 +736,7 @@ void debug_object_assert_init(void *addr, struct debug_obj_descr *descr)
> struct debug_bucket *db;
> struct debug_obj *obj;
> unsigned long flags;
> + bool debug_printobj = false;
>
> if (!debug_objects_enabled)
> return;
> @@ -732,22 +752,25 @@ void debug_object_assert_init(void *addr, struct debug_obj_descr *descr)
> if (obj->astate == expect)
> obj->astate = next;
> else
> - debug_print_object(obj, "active_state");
> + debug_printobj = true;
> break;
>
> default:
> - debug_print_object(obj, "active_state");
> + debug_printobj = true;
> break;
> }
> - } else {
> + }
> +
> + raw_spin_unlock_irqrestore(&db->lock, flags);
> + if (!obj) {
> struct debug_obj o = { .object = addr,
> .state = ODEBUG_STATE_NOTAVAILABLE,
> .descr = descr };
>
> debug_print_object(&o, "active_state");
> + } else if (debug_printobj) {
> + debug_print_object(obj, "active_state");
> }
> -
> - raw_spin_unlock_irqrestore(&db->lock, flags);
> }
> EXPORT_SYMBOL_GPL(debug_object_active_state);
>
> @@ -783,10 +806,10 @@ static void __debug_check_no_obj_freed(const void *address, unsigned long size)
>
> switch (obj->state) {
> case ODEBUG_STATE_ACTIVE:
> - debug_print_object(obj, "free");
> descr = obj->descr;
> state = obj->state;
> raw_spin_unlock_irqrestore(&db->lock, flags);
> + debug_print_object(obj, "free");
> debug_object_fixup(descr->fixup_free,
> (void *) oaddr, state);
> goto repeat;

As a side note, one of the test systems that I used generated a
debugobjects splat in the bootup process and the system hanged
afterward. Applying this patch alone fix the hanging problem and the
system booted up successfully. So it is not really a good idea to call
printk() while holding a raw spinlock.

Cheers,
Longman