INFO: task kworker/0:2:153 blocked for more than 143 seconds. Not tainted 6.1.0-rc5-syzkaller-00015-g81e7cfa3a9eb #0 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. task:kworker/0:2 state:D stack:26984 pid:153 ppid:2 flags:0x00004000 Workqueue: events rfkill_global_led_trigger_worker Call Trace: context_switch kernel/sched/core.c:5191 [inline] __schedule+0xae9/0x53f0 kernel/sched/core.c:6503 schedule+0xde/0x1b0 kernel/sched/core.c:6579 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6638 __mutex_lock_common kernel/locking/mutex.c:679 [inline] __mutex_lock+0xa48/0x1360 kernel/locking/mutex.c:747 rfkill_global_led_trigger_worker+0x1b/0x120 net/rfkill/core.c:181 process_one_work+0x9bf/0x1710 kernel/workqueue.c:2289 worker_thread+0x669/0x1090 kernel/workqueue.c:2436 kthread+0x2e8/0x3a0 kernel/kthread.c:376 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:306 INFO: task syz-executor369:3665 blocked for more than 143 seconds. Not tainted 6.1.0-rc5-syzkaller-00015-g81e7cfa3a9eb #0 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. task:syz-executor369 state:D stack:26344 pid:3665 ppid:3663 flags:0x20004002 Call Trace: context_switch kernel/sched/core.c:5191 [inline] __schedule+0xae9/0x53f0 kernel/sched/core.c:6503 schedule+0xde/0x1b0 kernel/sched/core.c:6579 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6638 __mutex_lock_common kernel/locking/mutex.c:679 [inline] __mutex_lock+0xa48/0x1360 kernel/locking/mutex.c:747 rfkill_unregister+0xde/0x2c0 net/rfkill/core.c:1130 nfc_unregister_device+0x96/0x330 net/nfc/core.c:1167 virtual_ncidev_close+0x71/0x90 drivers/nfc/virtual_ncidev.c:166 __fput+0x27c/0xa90 fs/file_table.c:320 task_work_run+0x16f/0x270 kernel/task_work.c:179 exit_task_work include/linux/task_work.h:38 [inline] do_exit+0xb3d/0x2a30 kernel/exit.c:820 do_group_exit+0xd4/0x2a0 kernel/exit.c:950 __do_sys_exit_group kernel/exit.c:961 [inline] __se_sys_exit_group kernel/exit.c:959 [inline] __ia32_sys_exit_group+0x3e/0x50 kernel/exit.c:959 do_syscall_32_irqs_on arch/x86/entry/common.c:112 [inline] __do_fast_syscall_32+0x65/0xf0 arch/x86/entry/common.c:178 do_fast_syscall_32+0x33/0x70 arch/x86/entry/common.c:203 entry_SYSENTER_compat_after_hwframe+0x70/0x82 RIP: 0023:0xf7e99549 RSP: 002b:00000000ffe582ac EFLAGS: 00000292 ORIG_RAX: 00000000000000fc RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 0000000000000000 RDX: 00000000f7f3efa0 RSI: 00000000f7f3f358 RDI: 00000000f7f3f358 RBP: 00000000f7f3f8c8 R08: 0000000000000000 R09: 0000000000000000 R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000 R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 INFO: task syz-executor369:3683 blocked for more than 143 seconds. Not tainted 6.1.0-rc5-syzkaller-00015-g81e7cfa3a9eb #0 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. task:syz-executor369 state:D stack:27984 pid:3683 ppid:3666 flags:0x20004004 Call Trace: context_switch kernel/sched/core.c:5191 [inline] __schedule+0xae9/0x53f0 kernel/sched/core.c:6503 schedule+0xde/0x1b0 kernel/sched/core.c:6579 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6638 __mutex_lock_common kernel/locking/mutex.c:679 [inline] __mutex_lock+0xa48/0x1360 kernel/locking/mutex.c:747 device_lock include/linux/device.h:835 [inline] nfc_dev_down+0x2d/0x2d0 net/nfc/core.c:143 nfc_rfkill_set_block+0x33/0xd0 net/nfc/core.c:179 rfkill_set_block+0x1f9/0x540 net/rfkill/core.c:345 rfkill_fop_write+0x2c7/0x570 net/rfkill/core.c:1286 vfs_write+0x2db/0xdd0 fs/read_write.c:582 ksys_write+0x1ec/0x250 fs/read_write.c:637 do_syscall_32_irqs_on arch/x86/entry/common.c:112 [inline] __do_fast_syscall_32+0x65/0xf0 arch/x86/entry/common.c:178 do_fast_syscall_32+0x33/0x70 arch/x86/entry/common.c:203 entry_SYSENTER_compat_after_hwframe+0x70/0x82 RIP: 0023:0xf7e99549 RSP: 002b:00000000ffe5830c EFLAGS: 00000246 ORIG_RAX: 0000000000000004 RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 0000000020000000 RDX: 0000000000000008 RSI: 0000000003700000 RDI: 0000000001000000 RBP: 000000000007798f R08: 0000000000000000 R09: 0000000000000000 R10: 0000000000000000 R11: 0000000000000282 R12: 0000000000000000 R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 INFO: task syz-executor369:3684 blocked for more than 144 seconds. Not tainted 6.1.0-rc5-syzkaller-00015-g81e7cfa3a9eb #0 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. task:syz-executor369 state:D stack:28200 pid:3684 ppid:3670 flags:0x20004004 Call Trace: context_switch kernel/sched/core.c:5191 [inline] __schedule+0xae9/0x53f0 kernel/sched/core.c:6503 schedule+0xde/0x1b0 kernel/sched/core.c:6579 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6638 __mutex_lock_common kernel/locking/mutex.c:679 [inline] __mutex_lock+0xa48/0x1360 kernel/locking/mutex.c:747 misc_open+0x63/0x4a0 drivers/char/misc.c:107 chrdev_open+0x26a/0x770 fs/char_dev.c:414 do_dentry_open+0x6cc/0x13f0 fs/open.c:882 do_open fs/namei.c:3557 [inline] path_openat+0x1bf6/0x2860 fs/namei.c:3713 do_filp_open+0x1ba/0x410 fs/namei.c:3740 do_sys_openat2+0x16d/0x4c0 fs/open.c:1310 do_sys_open fs/open.c:1326 [inline] __do_compat_sys_openat fs/open.c:1386 [inline] __se_compat_sys_openat fs/open.c:1384 [inline] __ia32_compat_sys_openat+0x143/0x1f0 fs/open.c:1384 do_syscall_32_irqs_on arch/x86/entry/common.c:112 [inline] __do_fast_syscall_32+0x65/0xf0 arch/x86/entry/common.c:178 do_fast_syscall_32+0x33/0x70 arch/x86/entry/common.c:203 entry_SYSENTER_compat_after_hwframe+0x70/0x82 RIP: 0023:0xf7e99549 RSP: 002b:00000000ffe582fc EFLAGS: 00000282 ORIG_RAX: 0000000000000127 RAX: ffffffffffffffda RBX: 00000000ffffff9c RCX: 0000000020000080 RDX: 0000000000022002 RSI: 0000000000000000 RDI: 00000000f7f0a03f RBP: 0000000000000012 R08: 0000000000000000 R09: 0000000000000000 R10: 0000000000000000 R11: 0000000000000282 R12: 0000000000000000 R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 INFO: task syz-executor369:3685 blocked for more than 144 seconds. Not tainted 6.1.0-rc5-syzkaller-00015-g81e7cfa3a9eb #0 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. task:syz-executor369 state:D stack:28200 pid:3685 ppid:3664 flags:0x20000004 Call Trace: context_switch kernel/sched/core.c:5191 [inline] __schedule+0xae9/0x53f0 kernel/sched/core.c:6503 schedule+0xde/0x1b0 kernel/sched/core.c:6579 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6638 __mutex_lock_common kernel/locking/mutex.c:679 [inline] __mutex_lock+0xa48/0x1360 kernel/locking/mutex.c:747 rfkill_fop_open+0x149/0x760 net/rfkill/core.c:1163 misc_open+0x37a/0x4a0 drivers/char/misc.c:143 chrdev_open+0x26a/0x770 fs/char_dev.c:414 do_dentry_open+0x6cc/0x13f0 fs/open.c:882 do_open fs/namei.c:3557 [inline] path_openat+0x1bf6/0x2860 fs/namei.c:3713 do_filp_open+0x1ba/0x410 fs/namei.c:3740 do_sys_openat2+0x16d/0x4c0 fs/open.c:1310 do_sys_open fs/open.c:1326 [inline] __do_compat_sys_openat fs/open.c:1386 [inline] __se_compat_sys_openat fs/open.c:1384 [inline] __ia32_compat_sys_openat+0x143/0x1f0 fs/open.c:1384 do_syscall_32_irqs_on arch/x86/entry/common.c:112 [inline] __do_fast_syscall_32+0x65/0xf0 arch/x86/entry/common.c:178 do_fast_syscall_32+0x33/0x70 arch/x86/entry/common.c:203 entry_SYSENTER_compat_after_hwframe+0x70/0x82 RIP: 0023:0xf7e99549 RSP: 002b:00000000ffe582fc EFLAGS: 00000282 ORIG_RAX: 0000000000000127 RAX: ffffffffffffffda RBX: 00000000ffffff9c RCX: 0000000020000080 RDX: 0000000000022002 RSI: 0000000000000000 RDI: 00000000f7f0a03f RBP: 0000000000000012 R08: 0000000000000000 R09: 0000000000000000 R10: 0000000000000000 R11: 0000000000000282 R12: 0000000000000000 R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 INFO: task syz-executor369:3686 blocked for more than 144 seconds. Not tainted 6.1.0-rc5-syzkaller-00015-g81e7cfa3a9eb #0 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. task:syz-executor369 state:D stack:28200 pid:3686 ppid:3667 flags:0x20000004 Call Trace: context_switch kernel/sched/core.c:5191 [inline] __schedule+0xae9/0x53f0 kernel/sched/core.c:6503 schedule+0xde/0x1b0 kernel/sched/core.c:6579 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6638 __mutex_lock_common kernel/locking/mutex.c:679 [inline] __mutex_lock+0xa48/0x1360 kernel/locking/mutex.c:747 misc_open+0x63/0x4a0 drivers/char/misc.c:107 chrdev_open+0x26a/0x770 fs/char_dev.c:414 do_dentry_open+0x6cc/0x13f0 fs/open.c:882 do_open fs/namei.c:3557 [inline] path_openat+0x1bf6/0x2860 fs/namei.c:3713 do_filp_open+0x1ba/0x410 fs/namei.c:3740 do_sys_openat2+0x16d/0x4c0 fs/open.c:1310 do_sys_open fs/open.c:1326 [inline] __do_compat_sys_openat fs/open.c:1386 [inline] __se_compat_sys_openat fs/open.c:1384 [inline] __ia32_compat_sys_openat+0x143/0x1f0 fs/open.c:1384 do_syscall_32_irqs_on arch/x86/entry/common.c:112 [inline] __do_fast_syscall_32+0x65/0xf0 arch/x86/entry/common.c:178 do_fast_syscall_32+0x33/0x70 arch/x86/entry/common.c:203 entry_SYSENTER_compat_after_hwframe+0x70/0x82 RIP: 0023:0xf7e99549 RSP: 002b:00000000ffe582fc EFLAGS: 00000282 ORIG_RAX: 0000000000000127 RAX: ffffffffffffffda RBX: 00000000ffffff9c RCX: 0000000020002100 RDX: 0000000000000002 RSI: 0000000000000000 RDI: 00000000f7f0a03f RBP: 0000000000000012 R08: 0000000000000000 R09: 0000000000000000 R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000 R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 INFO: task syz-executor369:3687 blocked for more than 144 seconds. Not tainted 6.1.0-rc5-syzkaller-00015-g81e7cfa3a9eb #0 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. task:syz-executor369 state:D stack:28200 pid:3687 ppid:3668 flags:0x20004004 Call Trace: context_switch kernel/sched/core.c:5191 [inline] __schedule+0xae9/0x53f0 kernel/sched/core.c:6503 schedule+0xde/0x1b0 kernel/sched/core.c:6579 schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6638 __mutex_lock_common kernel/locking/mutex.c:679 [inline] __mutex_lock+0xa48/0x1360 kernel/locking/mutex.c:747 misc_open+0x63/0x4a0 drivers/char/misc.c:107 chrdev_open+0x26a/0x770 fs/char_dev.c:414 do_dentry_open+0x6cc/0x13f0 fs/open.c:882 do_open fs/namei.c:3557 [inline] path_openat+0x1bf6/0x2860 fs/namei.c:3713 do_filp_open+0x1ba/0x410 fs/namei.c:3740 do_sys_openat2+0x16d/0x4c0 fs/open.c:1310 do_sys_open fs/open.c:1326 [inline] __do_compat_sys_openat fs/open.c:1386 [inline] __se_compat_sys_openat fs/open.c:1384 [inline] __ia32_compat_sys_openat+0x143/0x1f0 fs/open.c:1384 do_syscall_32_irqs_on arch/x86/entry/common.c:112 [inline] __do_fast_syscall_32+0x65/0xf0 arch/x86/entry/common.c:178 do_fast_syscall_32+0x33/0x70 arch/x86/entry/common.c:203 entry_SYSENTER_compat_after_hwframe+0x70/0x82 RIP: 0023:0xf7e99549 RSP: 002b:00000000ffe582fc EFLAGS: 00000282 ORIG_RAX: 0000000000000127 RAX: ffffffffffffffda RBX: 00000000ffffff9c RCX: 0000000020002100 RDX: 0000000000000002 RSI: 0000000000000000 RDI: 00000000f7f0a03f RBP: 0000000000000012 R08: 0000000000000000 R09: 0000000000000000 R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000 R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 Showing all locks held in the system: 1 lock held by rcu_tasks_kthre/12: #0: ffffffff8c58f0f0 (rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x26/0xc70 kernel/rcu/tasks.h:507 1 lock held by rcu_tasks_trace/13: #0: ffffffff8c58edf0 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x26/0xc70 kernel/rcu/tasks.h:507 1 lock held by khungtaskd/28: #0: ffffffff8c58fc40 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x57/0x264 kernel/locking/lockdep.c:6494 3 locks held by kworker/0:2/153: #0: ffff888012064d38 ((wq_completion)events){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline] #0: ffff888012064d38 ((wq_completion)events){+.+.}-{0:0}, at: arch_atomic_long_set include/linux/atomic/atomic-long.h:41 [inline] #0: ffff888012064d38 ((wq_completion)events){+.+.}-{0:0}, at: atomic_long_set include/linux/atomic/atomic-instrumented.h:1280 [inline] #0: ffff888012064d38 ((wq_completion)events){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:636 [inline] #0: ffff888012064d38 ((wq_completion)events){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:663 [inline] #0: ffff888012064d38 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x86d/0x1710 kernel/workqueue.c:2260 #1: ffffc90002dbfda8 ((work_completion)(&rfkill_global_led_trigger_work)){+.+.}-{0:0}, at: process_one_work+0x8a1/0x1710 kernel/workqueue.c:2264 #2: ffffffff8e2ead68 (rfkill_global_mutex){+.+.}-{3:3}, at: rfkill_global_led_trigger_worker+0x1b/0x120 net/rfkill/core.c:181 1 lock held by klogd/2986: #0: ffff8880b9b3b158 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested+0x2f/0x120 kernel/sched/core.c:537 2 locks held by getty/3316: #0: ffff88802899e098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x26/0x80 drivers/tty/tty_ldisc.c:244 #1: ffffc900031262f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0xef4/0x13e0 drivers/tty/n_tty.c:2177 2 locks held by syz-executor369/3665: #0: ffff888028bad100 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:835 [inline] #0: ffff888028bad100 (&dev->mutex){....}-{3:3}, at: nfc_unregister_device+0x62/0x330 net/nfc/core.c:1165 #1: ffffffff8e2ead68 (rfkill_global_mutex){+.+.}-{3:3}, at: rfkill_unregister+0xde/0x2c0 net/rfkill/core.c:1130 2 locks held by syz-executor369/3683: #0: ffffffff8e2ead68 (rfkill_global_mutex){+.+.}-{3:3}, at: rfkill_fop_write+0x160/0x570 net/rfkill/core.c:1278 #1: ffff888028bad100 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:835 [inline] #1: ffff888028bad100 (&dev->mutex){....}-{3:3}, at: nfc_dev_down+0x2d/0x2d0 net/nfc/core.c:143 1 lock held by syz-executor369/3684: #0: ffffffff8d056e68 (misc_mtx){+.+.}-{3:3}, at: misc_open+0x63/0x4a0 drivers/char/misc.c:107 2 locks held by syz-executor369/3685: #0: ffffffff8d056e68 (misc_mtx){+.+.}-{3:3}, at: misc_open+0x63/0x4a0 drivers/char/misc.c:107 #1: ffffffff8e2ead68 (rfkill_global_mutex){+.+.}-{3:3}, at: rfkill_fop_open+0x149/0x760 net/rfkill/core.c:1163 1 lock held by syz-executor369/3686: #0: ffffffff8d056e68 (misc_mtx){+.+.}-{3:3}, at: misc_open+0x63/0x4a0 drivers/char/misc.c:107 1 lock held by syz-executor369/3687: #0: ffffffff8d056e68 (misc_mtx){+.+.}-{3:3}, at: misc_open+0x63/0x4a0 drivers/char/misc.c:107 ============================================= NMI backtrace for cpu 0 CPU: 0 PID: 28 Comm: khungtaskd Not tainted 6.1.0-rc5-syzkaller-00015-g81e7cfa3a9eb #0 Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/26/2022 Call Trace: __dump_stack lib/dump_stack.c:88 [inline] dump_stack_lvl+0xd1/0x138 lib/dump_stack.c:106 nmi_cpu_backtrace.cold+0x24/0x18a lib/nmi_backtrace.c:111 nmi_trigger_cpumask_backtrace+0x333/0x3c0 lib/nmi_backtrace.c:62 trigger_all_cpu_backtrace include/linux/nmi.h:148 [inline] check_hung_uninterruptible_tasks kernel/hung_task.c:220 [inline] watchdog+0xc75/0xfc0 kernel/hung_task.c:377 kthread+0x2e8/0x3a0 kernel/kthread.c:376 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:306 Sending NMI from CPU 0 to CPUs 1: NMI backtrace for cpu 1 CPU: 1 PID: 102 Comm: kworker/u4:4 Not tainted 6.1.0-rc5-syzkaller-00015-g81e7cfa3a9eb #0 Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/26/2022 Workqueue: events_unbound toggle_allocation_gate RIP: 0010:native_irq_disable arch/x86/include/asm/irqflags.h:40 [inline] RIP: 0010:arch_local_irq_disable arch/x86/include/asm/irqflags.h:75 [inline] RIP: 0010:arch_local_irq_save arch/x86/include/asm/irqflags.h:107 [inline] RIP: 0010:smp_call_function_many_cond+0x5fe/0x10a0 kernel/smp.c:977 Code: 24 66 8d 7e 31 ff 44 89 e6 e8 ce f5 0a 00 45 85 e4 0f 84 12 fb ff ff e8 10 f9 0a 00 0f 0b e9 06 fb ff ff e8 04 f9 0a 00 9c 5b 81 e3 00 02 00 00 31 ff 48 89 de e8 c1 f5 0a 00 48 85 db 0f 85 RSP: 0018:ffffc900015b7970 EFLAGS: 00000293 RAX: 0000000000000000 RBX: 0000000000000293 RCX: 0000000000000000 RDX: ffff8880192bba80 RSI: ffffffff8175207c RDI: 0000000000000001 RBP: 0000000000000001 R08: 0000000000000001 R09: 0000000000000000 R10: 0000000000000001 R11: 0000000000000000 R12: ffff8880b9b3c290 R13: 0000000000000001 R14: 0000000000000002 R15: dffffc0000000000 FS: 0000000000000000(0000) GS:ffff8880b9b00000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 CR2: 000055e5aff82000 CR3: 000000000c28e000 CR4: 00000000003506e0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 Call Trace: on_each_cpu_cond_mask+0x5a/0xa0 kernel/smp.c:1155 on_each_cpu include/linux/smp.h:71 [inline] text_poke_sync arch/x86/kernel/alternative.c:1311 [inline] text_poke_bp_batch+0x22e/0x6b0 arch/x86/kernel/alternative.c:1502 text_poke_flush arch/x86/kernel/alternative.c:1670 [inline] text_poke_flush arch/x86/kernel/alternative.c:1667 [inline] text_poke_finish+0x1a/0x30 arch/x86/kernel/alternative.c:1677 arch_jump_label_transform_apply+0x17/0x30 arch/x86/kernel/jump_label.c:146 jump_label_update+0x32f/0x410 kernel/jump_label.c:801 static_key_disable_cpuslocked+0x156/0x1b0 kernel/jump_label.c:207 static_key_disable+0x1a/0x20 kernel/jump_label.c:215 toggle_allocation_gate mm/kfence/core.c:814 [inline] toggle_allocation_gate+0x187/0x390 mm/kfence/core.c:792 process_one_work+0x9bf/0x1710 kernel/workqueue.c:2289 worker_thread+0x669/0x1090 kernel/workqueue.c:2436 kthread+0x2e8/0x3a0 kernel/kthread.c:376 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:306 INFO: NMI handler (nmi_cpu_backtrace_handler) took too long to run: 1.090 msecs