Re: [PATCH v4 00/32] ldisc patchset

[Sasha Levin]

On 02/23/2013 01:43 PM, Peter Hurley wrote:
> On Sat, 2013-02-23 at 10:24 -0500, Sasha Levin wrote:
>> On 02/22/2013 01:37 PM, Peter Hurley wrote:
>>> On Thu, 2013-02-21 at 08:38 -0500, Peter Hurley wrote:
>>>> On Thu, 2013-02-21 at 08:16 -0500, Sasha Levin wrote:
>>>>> On 02/20/2013 03:02 PM, Peter Hurley wrote:
>>>>>> Sasha and Dave, my trinity testbeds die in other areas right now;
>>>>>> I would really appreciate if you would please re-test this series.
>>>>>
>>>>> Hi Peter,
>>>>>
>>>>> I saw this twice in overnight fuzzing:
>>>>>
>>>>> [ 1473.912280] =================================
>>>>> [ 1473.913180] [ BUG: bad contention detected! ]
>>>>> [ 1473.914071] 3.8.0-next-20130220-sasha-00038-g1ad55df-dirty #8 Tainted: G        W
>>>>> [ 1473.915684] ---------------------------------
>>>>> [ 1473.916549] kworker/1:1/361 is trying to contend lock (&tty->ldisc_sem) at:
>>>>> [ 1473.918031] [<ffffffff81c493df>] tty_ldisc_ref+0x1f/0x60
>>>>> [ 1473.919060] but there are no locks held!
>>>>
>>>> Ahh, of course. That explains why the rwsem trylock doesn't track lock
>>>> stats -- because by the time lock_contended() is called, up_write()
>>>> could have just called lockdep_release(), so that it appears as if the
>>>> lock has been released when in fact it has not but is about to.
>>>>
>>>> I'll just remove the lock contention test from the trylocks.
>>>
>>> Hi Sasha,
>>>
>>> Sorry for the delay. I was actually looking into if I could tickle
>>> lockdep into just recording the lock contention without testing, but
>>> unfortunately, changes to where lockdep stores the contention now
>>> requires the lockdep state to have an existing owner.
>>>
>>> So here's the trivial patch:
>>
>> Hi Peter,
>>
>> After more fuzzing, I'm seeing this sort of hangs (which are new):
>>
>> [ 2644.723879] INFO: task trinity:17893 blocked for more than 120 seconds.
>> [ 2644.727112] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [ 2644.731916] trinity         D ffff8800a9c904a8  5192 17893   8043 0x00000000
>> [ 2644.733517]  ffff88006efb3a78 0000000000000002 ffff8800aa0c3b10 ffff8800bb3d7180
>> [ 2644.739350]  ffff880019103000 ffff880097a78000 ffff88006efb3a78 00000000001d7180
>> [ 2644.741459]  ffff880097a78000 ffff88006efb3fd8 00000000001d7180 00000000001d7180
>> [ 2644.746590] Call Trace:
>> [ 2644.747177]  [<ffffffff83db9909>] __schedule+0x2e9/0x3b0
>> [ 2644.748294]  [<ffffffff83db9b35>] schedule+0x55/0x60
>> [ 2644.752382]  [<ffffffff83db9e83>] schedule_preempt_disabled+0x13/0x20
>> [ 2644.753737]  [<ffffffff83db7fdd>] __mutex_lock_common+0x34d/0x560
>> [ 2644.759037]  [<ffffffff81c40893>] ? ptmx_open+0x83/0x190
>> [ 2644.760590]  [<ffffffff83db84b5>] ? __mutex_unlock_slowpath+0x185/0x1e0
>> [ 2644.762064]  [<ffffffff81c40893>] ? ptmx_open+0x83/0x190
>> [ 2644.768967]  [<ffffffff83db831f>] mutex_lock_nested+0x3f/0x50
>> [ 2644.770314]  [<ffffffff81c40893>] ptmx_open+0x83/0x190
>> [ 2644.771413]  [<ffffffff812917ae>] chrdev_open+0x11e/0x190
>> [ 2644.780456]  [<ffffffff81291690>] ? cdev_put+0x30/0x30
>> [ 2644.781421]  [<ffffffff8128af59>] do_dentry_open+0x1f9/0x310
>> [ 2644.785550]  [<ffffffff8128b0bc>] finish_open+0x4c/0x70
>> [ 2644.786724]  [<ffffffff8129c3eb>] do_last+0x61b/0x810
>> [ 2644.787676]  [<ffffffff8129c699>] path_openat+0xb9/0x4d0
>> [ 2644.791868]  [<ffffffff812ac278>] ? __alloc_fd+0x1e8/0x200
>> [ 2644.792817]  [<ffffffff81185214>] ? lock_release_nested+0xb4/0xf0
>> [ 2644.794010]  [<ffffffff81185331>] ? __lock_release+0xe1/0x100
>> [ 2644.797401]  [<ffffffff8129cebd>] do_filp_open+0x3d/0xa0
>> [ 2644.798467]  [<ffffffff812ac278>] ? __alloc_fd+0x1e8/0x200
>> [ 2644.799577]  [<ffffffff8128c51b>] do_sys_open+0x12b/0x1d0
>> [ 2644.804667]  [<ffffffff8128c5dc>] sys_open+0x1c/0x20
>> [ 2644.805542]  [<ffffffff83dc49d8>] tracesys+0xe1/0xe6
>> [ 2644.822807] 1 lock held by trinity/17893:
>> [ 2644.823685]  #0:  (tty_mutex){+.+.+.}, at: [<ffffffff81c40893>] ptmx_open+0x83/0x190
>>
>> The mutex is 'tty_mutex' at drivers/tty/pty.c:701 .
>>
>> I didn't grab sysrq-t this time since it was an overnight run, but I'll
>> try to grab one when it happens again.
> 
> Hi Sasha,
> 
> Can you please 'make drivers/tty/pty.lst'  for this kernel config and
> paste ptmx_open() here?
> 
> This report makes no sense: this stack trace shows this task waiting on
> a mutex that is not owned.

static int ptmx_open(struct inode *inode, struct file *filp)
{
 6c0:	55                   	push   %rbp
 6c1:	48 89 e5             	mov    %rsp,%rbp
 6c4:	48 83 ec 30          	sub    $0x30,%rsp
 6c8:	48 89 5d d8          	mov    %rbx,-0x28(%rbp)
 6cc:	48 89 f3             	mov    %rsi,%rbx
 6cf:	4c 89 65 e0          	mov    %r12,-0x20(%rbp)
 6d3:	49 89 fc             	mov    %rdi,%r12
 6d6:	4c 89 7d f8          	mov    %r15,-0x8(%rbp)
 6da:	4c 89 6d e8          	mov    %r13,-0x18(%rbp)
 6de:	4c 89 75 f0          	mov    %r14,-0x10(%rbp)
	struct tty_struct *tty;
	struct inode *slave_inode;
	int retval;
	int index;

	nonseekable_open(inode, filp);
 6e2:	e8 00 00 00 00       	callq  6e7 <ptmx_open+0x27>
			6e3: R_X86_64_PC32	nonseekable_open-0x4

	retval = tty_alloc_file(filp);
 6e7:	48 89 df             	mov    %rbx,%rdi
 6ea:	e8 00 00 00 00       	callq  6ef <ptmx_open+0x2f>
			6eb: R_X86_64_PC32	tty_alloc_file-0x4
	if (retval)
 6ef:	85 c0                	test   %eax,%eax
	int retval;
	int index;

	nonseekable_open(inode, filp);

	retval = tty_alloc_file(filp);
 6f1:	41 89 c7             	mov    %eax,%r15d
	if (retval)
 6f4:	0f 85 36 01 00 00    	jne    830 <ptmx_open+0x170>
		return retval;

	/* find a device that is not in use. */
	mutex_lock(&devpts_mutex);
 6fa:	31 f6                	xor    %esi,%esi
 6fc:	48 c7 c7 00 00 00 00 	mov    $0x0,%rdi
			6ff: R_X86_64_32S	.data+0x20
 703:	e8 00 00 00 00       	callq  708 <ptmx_open+0x48>
			704: R_X86_64_PC32	mutex_lock_nested-0x4
	index = devpts_new_index(inode);
 708:	4c 89 e7             	mov    %r12,%rdi
 70b:	e8 00 00 00 00       	callq  710 <ptmx_open+0x50>
			70c: R_X86_64_PC32	devpts_new_index-0x4
	if (index < 0) {
		retval = index;
		mutex_unlock(&devpts_mutex);
 710:	48 c7 c7 00 00 00 00 	mov    $0x0,%rdi
			713: R_X86_64_32S	.data+0x20
		return retval;

	/* find a device that is not in use. */
	mutex_lock(&devpts_mutex);
	index = devpts_new_index(inode);
	if (index < 0) {
 717:	85 c0                	test   %eax,%eax
	if (retval)
		return retval;

	/* find a device that is not in use. */
	mutex_lock(&devpts_mutex);
	index = devpts_new_index(inode);
 719:	41 89 c6             	mov    %eax,%r14d
	if (index < 0) {
 71c:	79 12                	jns    730 <ptmx_open+0x70>
		retval = index;
		mutex_unlock(&devpts_mutex);
 71e:	e8 00 00 00 00       	callq  723 <ptmx_open+0x63>
			71f: R_X86_64_PC32	mutex_unlock-0x4
		goto err_file;
 723:	45 89 f7             	mov    %r14d,%r15d
 726:	e9 fd 00 00 00       	jmpq   828 <ptmx_open+0x168>
 72b:	0f 1f 44 00 00       	nopl   0x0(%rax,%rax,1)
	}

	mutex_unlock(&devpts_mutex);
 730:	e8 00 00 00 00       	callq  735 <ptmx_open+0x75>
			731: R_X86_64_PC32	mutex_unlock-0x4

	mutex_lock(&tty_mutex);
 735:	31 f6                	xor    %esi,%esi
 737:	48 c7 c7 00 00 00 00 	mov    $0x0,%rdi
			73a: R_X86_64_32S	tty_mutex
 73e:	e8 00 00 00 00       	callq  743 <ptmx_open+0x83>
			73f: R_X86_64_PC32	mutex_lock_nested-0x4
	tty = tty_init_dev(ptm_driver, index);
 743:	48 8b 3d 00 00 00 00 	mov    0x0(%rip),%rdi        # 74a <ptmx_open+0x8a>
			746: R_X86_64_PC32	.bss-0x4
 74a:	44 89 f6             	mov    %r14d,%esi
 74d:	e8 00 00 00 00       	callq  752 <ptmx_open+0x92>
			74e: R_X86_64_PC32	tty_init_dev-0x4

	if (IS_ERR(tty)) {
 752:	48 3d 00 f0 ff ff    	cmp    $0xfffffffffffff000,%rax
	}

	mutex_unlock(&devpts_mutex);

	mutex_lock(&tty_mutex);
	tty = tty_init_dev(ptm_driver, index);
 758:	49 89 c5             	mov    %rax,%r13

	if (IS_ERR(tty)) {
 75b:	76 23                	jbe    780 <ptmx_open+0xc0>
err_release:
	tty_unlock(tty);
	tty_release(inode, filp);
	return retval;
out:
	mutex_unlock(&tty_mutex);
 75d:	48 c7 c7 00 00 00 00 	mov    $0x0,%rdi
			760: R_X86_64_32S	tty_mutex

	mutex_lock(&tty_mutex);
	tty = tty_init_dev(ptm_driver, index);

	if (IS_ERR(tty)) {
		retval = PTR_ERR(tty);
 764:	41 89 c7             	mov    %eax,%r15d
err_release:
	tty_unlock(tty);
	tty_release(inode, filp);
	return retval;
out:
	mutex_unlock(&tty_mutex);
 767:	e8 00 00 00 00       	callq  76c <ptmx_open+0xac>
			768: R_X86_64_PC32	mutex_unlock-0x4
	devpts_kill_index(inode, index);
 76c:	44 89 f6             	mov    %r14d,%esi
 76f:	4c 89 e7             	mov    %r12,%rdi
 772:	e8 00 00 00 00       	callq  777 <ptmx_open+0xb7>
			773: R_X86_64_PC32	devpts_kill_index-0x4
 777:	e9 ac 00 00 00       	jmpq   828 <ptmx_open+0x168>
 77c:	0f 1f 40 00          	nopl   0x0(%rax)
		goto out;
	}

	/* The tty returned here is locked so we can safely
	   drop the mutex */
	mutex_unlock(&tty_mutex);
 780:	48 c7 c7 00 00 00 00 	mov    $0x0,%rdi
			783: R_X86_64_32S	tty_mutex
 787:	e8 00 00 00 00       	callq  78c <ptmx_open+0xcc>
			788: R_X86_64_PC32	mutex_unlock-0x4
 78c:	f0 41 80 8d da 03 00 	lock orb $0x1,0x3da(%r13)
 793:	00 01

	set_bit(TTY_PTY_LOCK, &tty->flags); /* LOCK THE SLAVE */
	tty->driver_data = inode;

	tty_add_file(tty, filp);
 795:	48 89 de             	mov    %rbx,%rsi
 798:	4c 89 ef             	mov    %r13,%rdi
	/* The tty returned here is locked so we can safely
	   drop the mutex */
	mutex_unlock(&tty_mutex);

	set_bit(TTY_PTY_LOCK, &tty->flags); /* LOCK THE SLAVE */
	tty->driver_data = inode;
 79b:	4d 89 a5 18 05 00 00 	mov    %r12,0x518(%r13)

	tty_add_file(tty, filp);
 7a2:	e8 00 00 00 00       	callq  7a7 <ptmx_open+0xe7>
			7a3: R_X86_64_PC32	tty_add_file-0x4

	slave_inode = devpts_pty_new(inode,
 7a7:	49 8b 8d f8 03 00 00 	mov    0x3f8(%r13),%rcx
			MKDEV(UNIX98_PTY_SLAVE_MAJOR, index), index,
 7ae:	44 89 f6             	mov    %r14d,%esi
 7b1:	81 ce 00 00 80 08    	or     $0x8800000,%esi
	set_bit(TTY_PTY_LOCK, &tty->flags); /* LOCK THE SLAVE */
	tty->driver_data = inode;

	tty_add_file(tty, filp);

	slave_inode = devpts_pty_new(inode,
 7b7:	44 89 f2             	mov    %r14d,%edx
 7ba:	4c 89 e7             	mov    %r12,%rdi
 7bd:	e8 00 00 00 00       	callq  7c2 <ptmx_open+0x102>
			7be: R_X86_64_PC32	devpts_pty_new-0x4
			MKDEV(UNIX98_PTY_SLAVE_MAJOR, index), index,
			tty->link);
	if (IS_ERR(slave_inode)) {
 7c2:	48 3d 00 f0 ff ff    	cmp    $0xfffffffffffff000,%rax
 7c8:	76 06                	jbe    7d0 <ptmx_open+0x110>
		retval = PTR_ERR(slave_inode);
 7ca:	41 89 c7             	mov    %eax,%r15d
		goto err_release;
 7cd:	eb 41                	jmp    810 <ptmx_open+0x150>
 7cf:	90                   	nop
	}
	tty->link->driver_data = slave_inode;
 7d0:	49 8b 95 f8 03 00 00 	mov    0x3f8(%r13),%rdx

	retval = ptm_driver->ops->open(tty, filp);
 7d7:	48 89 de             	mov    %rbx,%rsi
 7da:	4c 89 ef             	mov    %r13,%rdi
			tty->link);
	if (IS_ERR(slave_inode)) {
		retval = PTR_ERR(slave_inode);
		goto err_release;
	}
	tty->link->driver_data = slave_inode;
 7dd:	48 89 82 18 05 00 00 	mov    %rax,0x518(%rdx)

	retval = ptm_driver->ops->open(tty, filp);
 7e4:	48 8b 05 00 00 00 00 	mov    0x0(%rip),%rax        # 7eb <ptmx_open+0x12b>
			7e7: R_X86_64_PC32	.bss-0x4
 7eb:	48 8b 80 a0 00 00 00 	mov    0xa0(%rax),%rax
 7f2:	ff 50 18             	callq  *0x18(%rax)
	if (retval)
 7f5:	85 c0                	test   %eax,%eax
		retval = PTR_ERR(slave_inode);
		goto err_release;
	}
	tty->link->driver_data = slave_inode;

	retval = ptm_driver->ops->open(tty, filp);
 7f7:	41 89 c7             	mov    %eax,%r15d
	if (retval)
 7fa:	75 14                	jne    810 <ptmx_open+0x150>
		goto err_release;

	tty_unlock(tty);
 7fc:	4c 89 ef             	mov    %r13,%rdi
 7ff:	e8 00 00 00 00       	callq  804 <ptmx_open+0x144>
			800: R_X86_64_PC32	tty_unlock-0x4
	return 0;
 804:	eb 2a                	jmp    830 <ptmx_open+0x170>
 806:	66 2e 0f 1f 84 00 00 	nopw   %cs:0x0(%rax,%rax,1)
 80d:	00 00 00
err_release:
	tty_unlock(tty);
 810:	4c 89 ef             	mov    %r13,%rdi
 813:	e8 00 00 00 00       	callq  818 <ptmx_open+0x158>
			814: R_X86_64_PC32	tty_unlock-0x4
	tty_release(inode, filp);
 818:	48 89 de             	mov    %rbx,%rsi
 81b:	4c 89 e7             	mov    %r12,%rdi
 81e:	e8 00 00 00 00       	callq  823 <ptmx_open+0x163>
			81f: R_X86_64_PC32	tty_release-0x4
	return retval;
 823:	eb 0b                	jmp    830 <ptmx_open+0x170>
 825:	0f 1f 00             	nopl   (%rax)
out:
	mutex_unlock(&tty_mutex);
	devpts_kill_index(inode, index);
err_file:
	tty_free_file(filp);
 828:	48 89 df             	mov    %rbx,%rdi
 82b:	e8 00 00 00 00       	callq  830 <ptmx_open+0x170>
			82c: R_X86_64_PC32	tty_free_file-0x4
	return retval;
}
 830:	44 89 f8             	mov    %r15d,%eax
 833:	48 8b 5d d8          	mov    -0x28(%rbp),%rbx
 837:	4c 8b 65 e0          	mov    -0x20(%rbp),%r12
 83b:	4c 8b 6d e8          	mov    -0x18(%rbp),%r13
 83f:	4c 8b 75 f0          	mov    -0x10(%rbp),%r14
 843:	4c 8b 7d f8          	mov    -0x8(%rbp),%r15
 847:	c9                   	leaveq
 848:	c3                   	retq
 849:	0f 1f 80 00 00 00 00 	nopl   0x0(%rax)


Thanks,
Sasha

--
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/