[igt-dev] [PATCH i-g-t] lib/igt_core: Reinitialize print mutex in child process

[igt-dev] [PATCH i-g-t] lib/igt_core: Reinitialize print mutex in child process

[Zbigniew Kempczyński]

IGT are prone to deadlock in igt_log() in following scenario:

1. Parent process creates additional thread which for example
   is doing endless loop
2. Thread sometimes is logging to console using igt_info().
   This locks and unlocks print_mutex.
3. If in the meantime parent process will spawn it can be
   spawned with print_mutex locked. If in the child process
   it will do igt_info() it will deadlock.

We should reinitialize print_mutex in child process to avoid
use inherited value.

Signed-off-by: Zbigniew Kempczyński <zbigniew.kempczynski@intel.com>
Cc: Petri Latvala <petri.latvala@intel.com>
---
 lib/igt_core.c | 8 +++++---
 1 file changed, 5 insertions(+), 3 deletions(-)

diff --git a/lib/igt_core.c b/lib/igt_core.c
index cedd8168..722202ae 100644
--- a/lib/igt_core.c
+++ b/lib/igt_core.c
@@ -2271,6 +2271,8 @@ static void children_exit_handler(int sig)
 		;
 }
 
+static pthread_mutex_t print_mutex = PTHREAD_MUTEX_INITIALIZER;
+
 bool __igt_fork(void)
 {
 	internal_assert(!test_with_subtests || in_subtest,
@@ -2300,6 +2302,7 @@ bool __igt_fork(void)
 		igt_assert(0);
 	case 0:
 		test_child = true;
+		pthread_mutex_init(&print_mutex, NULL);
 		exit_handler_count = 0;
 		reset_helper_process_list();
 		oom_adjust_for_doom();
@@ -2737,8 +2740,6 @@ void igt_vlog(const char *domain, enum igt_log_level level, const char *format,
 		"NONE"
 	};
 
-	static pthread_mutex_t print_mutex = PTHREAD_MUTEX_INITIALIZER;
-
 	assert(format);
 
 #ifdef __GLIBC__
@@ -2747,7 +2748,6 @@ void igt_vlog(const char *domain, enum igt_log_level level, const char *format,
 	program_name = command_str;
 #endif
 
-
 	if (igt_thread_is_main()) {
 		thread_id = strdup("");
 	} else {
@@ -2823,6 +2823,8 @@ out:
 	free(line);
 }
 
+
+
 static const char *timeout_op;
 static void __attribute__((noreturn)) igt_alarm_handler(int signal)
 {
-- 
2.26.0

_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

[igt-dev] ✗ Fi.CI.BAT: failure for lib/igt_core: Reinitialize print mutex in child process

[Patchwork]

[-- Attachment #1.1: Type: text/plain, Size: 5348 bytes --]

== Series Details ==

Series: lib/igt_core: Reinitialize print mutex in child process
URL   : https://patchwork.freedesktop.org/series/82154/
State : failure

== Summary ==

CI Bug Log - changes from CI_DRM_9063 -> IGTPW_5014
====================================================

Summary
-------

  **FAILURE**

  Serious unknown changes coming with IGTPW_5014 absolutely need to be
  verified manually.
  
  If you think the reported changes have nothing to do with the changes
  introduced in IGTPW_5014, please notify your bug team to allow them
  to document this new failure mode, which will reduce false positives in CI.

  External URL: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_5014/index.html

Possible new issues
-------------------

  Here are the unknown changes that may have been introduced in IGTPW_5014:

### IGT changes ###

#### Possible regressions ####

  * igt@i915_selftest@live@gt_contexts:
    - fi-ilk-650:         [PASS][1] -> [DMESG-FAIL][2]
   [1]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_9063/fi-ilk-650/igt@i915_selftest@live@gt_contexts.html
   [2]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_5014/fi-ilk-650/igt@i915_selftest@live@gt_contexts.html

  
Known issues
------------

  Here are the changes found in IGTPW_5014 that come from known issues:

### IGT changes ###

#### Possible fixes ####

  * igt@i915_module_load@reload:
    - {fi-ehl-1}:         [DMESG-WARN][3] ([i915#1982]) -> [PASS][4]
   [3]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_9063/fi-ehl-1/igt@i915_module_load@reload.html
   [4]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_5014/fi-ehl-1/igt@i915_module_load@reload.html

  * igt@kms_cursor_legacy@basic-busy-flip-before-cursor-atomic:
    - {fi-kbl-7560u}:     [DMESG-WARN][5] ([i915#1982]) -> [PASS][6]
   [5]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_9063/fi-kbl-7560u/igt@kms_cursor_legacy@basic-busy-flip-before-cursor-atomic.html
   [6]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_5014/fi-kbl-7560u/igt@kms_cursor_legacy@basic-busy-flip-before-cursor-atomic.html

  * igt@kms_cursor_legacy@basic-busy-flip-before-cursor-legacy:
    - fi-icl-u2:          [DMESG-WARN][7] ([i915#1982]) -> [PASS][8] +1 similar issue
   [7]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_9063/fi-icl-u2/igt@kms_cursor_legacy@basic-busy-flip-before-cursor-legacy.html
   [8]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_5014/fi-icl-u2/igt@kms_cursor_legacy@basic-busy-flip-before-cursor-legacy.html

  * igt@vgem_basic@unload:
    - fi-skl-guc:         [DMESG-WARN][9] ([i915#2203]) -> [PASS][10]
   [9]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_9063/fi-skl-guc/igt@vgem_basic@unload.html
   [10]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_5014/fi-skl-guc/igt@vgem_basic@unload.html

  
#### Warnings ####

  * igt@kms_cursor_legacy@basic-flip-before-cursor-varying-size:
    - fi-kbl-x1275:       [DMESG-WARN][11] ([i915#62] / [i915#92]) -> [DMESG-WARN][12] ([i915#62] / [i915#92] / [i915#95]) +1 similar issue
   [11]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_9063/fi-kbl-x1275/igt@kms_cursor_legacy@basic-flip-before-cursor-varying-size.html
   [12]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_5014/fi-kbl-x1275/igt@kms_cursor_legacy@basic-flip-before-cursor-varying-size.html

  * igt@kms_pipe_crc_basic@compare-crc-sanitycheck-pipe-c:
    - fi-kbl-x1275:       [DMESG-WARN][13] ([i915#62] / [i915#92] / [i915#95]) -> [DMESG-WARN][14] ([i915#62] / [i915#92]) +4 similar issues
   [13]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_9063/fi-kbl-x1275/igt@kms_pipe_crc_basic@compare-crc-sanitycheck-pipe-c.html
   [14]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_5014/fi-kbl-x1275/igt@kms_pipe_crc_basic@compare-crc-sanitycheck-pipe-c.html

  * igt@kms_pipe_crc_basic@suspend-read-crc-pipe-a:
    - fi-kbl-x1275:       [DMESG-WARN][15] ([i915#62] / [i915#92]) -> [DMESG-WARN][16] ([i915#1982] / [i915#62] / [i915#92])
   [15]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_9063/fi-kbl-x1275/igt@kms_pipe_crc_basic@suspend-read-crc-pipe-a.html
   [16]: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_5014/fi-kbl-x1275/igt@kms_pipe_crc_basic@suspend-read-crc-pipe-a.html

  
  {name}: This element is suppressed. This means it is ignored when computing
          the status of the difference (SUCCESS, WARNING, or FAILURE).

  [i915#1982]: https://gitlab.freedesktop.org/drm/intel/issues/1982
  [i915#2203]: https://gitlab.freedesktop.org/drm/intel/issues/2203
  [i915#62]: https://gitlab.freedesktop.org/drm/intel/issues/62
  [i915#92]: https://gitlab.freedesktop.org/drm/intel/issues/92
  [i915#95]: https://gitlab.freedesktop.org/drm/intel/issues/95


Participating hosts (46 -> 39)
------------------------------

  Missing    (7): fi-ilk-m540 fi-hsw-4200u fi-byt-squawks fi-bsw-cyan fi-ctg-p8600 fi-byt-clapper fi-bdw-samus 


Build changes
-------------

  * CI: CI-20190529 -> None
  * IGT: IGT_5790 -> IGTPW_5014

  CI-20190529: 20190529
  CI_DRM_9063: f5f96fda9af776f800f55d9631d1dea056d06d5f @ git://anongit.freedesktop.org/gfx-ci/linux
  IGTPW_5014: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_5014/index.html
  IGT_5790: 722a3eb9734f04030508d244df9dff55c5ab686c @ git://anongit.freedesktop.org/xorg/app/intel-gpu-tools

== Logs ==

For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_5014/index.html

[-- Attachment #1.2: Type: text/html, Size: 7058 bytes --]

[-- Attachment #2: Type: text/plain, Size: 154 bytes --]

_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

Re: [igt-dev] [PATCH i-g-t] lib/igt_core: Reinitialize print mutex in child process

[Petri Latvala]

On Mon, Sep 28, 2020 at 03:15:02PM +0200, Zbigniew Kempczyński wrote:
> IGT are prone to deadlock in igt_log() in following scenario:
> 
> 1. Parent process creates additional thread which for example
>    is doing endless loop
> 2. Thread sometimes is logging to console using igt_info().
>    This locks and unlocks print_mutex.
> 3. If in the meantime parent process will spawn it can be
>    spawned with print_mutex locked. If in the child process
>    it will do igt_info() it will deadlock.
> 
> We should reinitialize print_mutex in child process to avoid
> use inherited value.
> 
> Signed-off-by: Zbigniew Kempczyński <zbigniew.kempczynski@intel.com>
> Cc: Petri Latvala <petri.latvala@intel.com>
> ---

Are you able to type up a unit test in lib/tests/ that reproduces this
deadlock?

Code LGTM, Arek, do you spot anything amiss with this?


-- 
Petri Latvala



>  lib/igt_core.c | 8 +++++---
>  1 file changed, 5 insertions(+), 3 deletions(-)
> 
> diff --git a/lib/igt_core.c b/lib/igt_core.c
> index cedd8168..722202ae 100644
> --- a/lib/igt_core.c
> +++ b/lib/igt_core.c
> @@ -2271,6 +2271,8 @@ static void children_exit_handler(int sig)
>  		;
>  }
>  
> +static pthread_mutex_t print_mutex = PTHREAD_MUTEX_INITIALIZER;
> +
>  bool __igt_fork(void)
>  {
>  	internal_assert(!test_with_subtests || in_subtest,
> @@ -2300,6 +2302,7 @@ bool __igt_fork(void)
>  		igt_assert(0);
>  	case 0:
>  		test_child = true;
> +		pthread_mutex_init(&print_mutex, NULL);
>  		exit_handler_count = 0;
>  		reset_helper_process_list();
>  		oom_adjust_for_doom();
> @@ -2737,8 +2740,6 @@ void igt_vlog(const char *domain, enum igt_log_level level, const char *format,
>  		"NONE"
>  	};
>  
> -	static pthread_mutex_t print_mutex = PTHREAD_MUTEX_INITIALIZER;
> -
>  	assert(format);
>  
>  #ifdef __GLIBC__
> @@ -2747,7 +2748,6 @@ void igt_vlog(const char *domain, enum igt_log_level level, const char *format,
>  	program_name = command_str;
>  #endif
>  
> -
>  	if (igt_thread_is_main()) {
>  		thread_id = strdup("");
>  	} else {
> @@ -2823,6 +2823,8 @@ out:
>  	free(line);
>  }
>  
> +
> +
>  static const char *timeout_op;
>  static void __attribute__((noreturn)) igt_alarm_handler(int signal)
>  {
> -- 
> 2.26.0
> 
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

Re: [igt-dev] [PATCH i-g-t] lib/igt_core: Reinitialize print mutex in child process

[Arkadiusz Hiler]

On Mon, Sep 28, 2020 at 06:29:20PM +0300, Petri Latvala wrote:
> On Mon, Sep 28, 2020 at 03:15:02PM +0200, Zbigniew Kempczyński wrote:
> > IGT are prone to deadlock in igt_log() in following scenario:
> > 
> > 1. Parent process creates additional thread which for example
> >    is doing endless loop
> > 2. Thread sometimes is logging to console using igt_info().
> >    This locks and unlocks print_mutex.
> > 3. If in the meantime parent process will spawn it can be
> >    spawned with print_mutex locked. If in the child process
> >    it will do igt_info() it will deadlock.
> > 
> > We should reinitialize print_mutex in child process to avoid
> > use inherited value.
> > 
> > Signed-off-by: Zbigniew Kempczyński <zbigniew.kempczynski@intel.com>
> > Cc: Petri Latvala <petri.latvala@intel.com>
> > ---
> 
> Are you able to type up a unit test in lib/tests/ that reproduces this
> deadlock?
> 
> Code LGTM, Arek, do you spot anything amiss with this?

Other than the random whitespace changes the patch looks good. Thanks!

Mixing threading and forking is always 'fun' and people rarely think
about it upfront. I won't be surprised if we will find more things like
this :-)

-- 
Cheers,
Arek
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

Re: [igt-dev] [PATCH i-g-t] lib/igt_core: Reinitialize print mutex in child process

[Zbigniew Kempczyński]

On Mon, Sep 28, 2020 at 06:29:20PM +0300, Petri Latvala wrote:
> On Mon, Sep 28, 2020 at 03:15:02PM +0200, Zbigniew Kempczyński wrote:
> > IGT are prone to deadlock in igt_log() in following scenario:
> > 
> > 1. Parent process creates additional thread which for example
> >    is doing endless loop
> > 2. Thread sometimes is logging to console using igt_info().
> >    This locks and unlocks print_mutex.
> > 3. If in the meantime parent process will spawn it can be
> >    spawned with print_mutex locked. If in the child process
> >    it will do igt_info() it will deadlock.
> > 
> > We should reinitialize print_mutex in child process to avoid
> > use inherited value.
> > 
> > Signed-off-by: Zbigniew Kempczyński <zbigniew.kempczynski@intel.com>
> > Cc: Petri Latvala <petri.latvala@intel.com>
> > ---
> 
> Are you able to type up a unit test in lib/tests/ that reproduces this
> deadlock?

Sure, shouldn't take much time. 

--
Zbigniew

> 
> Code LGTM, Arek, do you spot anything amiss with this?
> 
> 
> -- 
> Petri Latvala
> 
> 
> 
> >  lib/igt_core.c | 8 +++++---
> >  1 file changed, 5 insertions(+), 3 deletions(-)
> > 
> > diff --git a/lib/igt_core.c b/lib/igt_core.c
> > index cedd8168..722202ae 100644
> > --- a/lib/igt_core.c
> > +++ b/lib/igt_core.c
> > @@ -2271,6 +2271,8 @@ static void children_exit_handler(int sig)
> >  		;
> >  }
> >  
> > +static pthread_mutex_t print_mutex = PTHREAD_MUTEX_INITIALIZER;
> > +
> >  bool __igt_fork(void)
> >  {
> >  	internal_assert(!test_with_subtests || in_subtest,
> > @@ -2300,6 +2302,7 @@ bool __igt_fork(void)
> >  		igt_assert(0);
> >  	case 0:
> >  		test_child = true;
> > +		pthread_mutex_init(&print_mutex, NULL);
> >  		exit_handler_count = 0;
> >  		reset_helper_process_list();
> >  		oom_adjust_for_doom();
> > @@ -2737,8 +2740,6 @@ void igt_vlog(const char *domain, enum igt_log_level level, const char *format,
> >  		"NONE"
> >  	};
> >  
> > -	static pthread_mutex_t print_mutex = PTHREAD_MUTEX_INITIALIZER;
> > -
> >  	assert(format);
> >  
> >  #ifdef __GLIBC__
> > @@ -2747,7 +2748,6 @@ void igt_vlog(const char *domain, enum igt_log_level level, const char *format,
> >  	program_name = command_str;
> >  #endif
> >  
> > -
> >  	if (igt_thread_is_main()) {
> >  		thread_id = strdup("");
> >  	} else {
> > @@ -2823,6 +2823,8 @@ out:
> >  	free(line);
> >  }
> >  
> > +
> > +
> >  static const char *timeout_op;
> >  static void __attribute__((noreturn)) igt_alarm_handler(int signal)
> >  {
> > -- 
> > 2.26.0
> > 
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

Re: [igt-dev] [PATCH i-g-t] lib/igt_core: Reinitialize print mutex in child process

[Zbigniew Kempczyński]

On Mon, Sep 28, 2020 at 08:37:12PM +0300, Arkadiusz Hiler wrote:
> On Mon, Sep 28, 2020 at 06:29:20PM +0300, Petri Latvala wrote:
> > On Mon, Sep 28, 2020 at 03:15:02PM +0200, Zbigniew Kempczyński wrote:
> > > IGT are prone to deadlock in igt_log() in following scenario:
> > > 
> > > 1. Parent process creates additional thread which for example
> > >    is doing endless loop
> > > 2. Thread sometimes is logging to console using igt_info().
> > >    This locks and unlocks print_mutex.
> > > 3. If in the meantime parent process will spawn it can be
> > >    spawned with print_mutex locked. If in the child process
> > >    it will do igt_info() it will deadlock.
> > > 
> > > We should reinitialize print_mutex in child process to avoid
> > > use inherited value.
> > > 
> > > Signed-off-by: Zbigniew Kempczyński <zbigniew.kempczynski@intel.com>
> > > Cc: Petri Latvala <petri.latvala@intel.com>
> > > ---
> > 
> > Are you able to type up a unit test in lib/tests/ that reproduces this
> > deadlock?
> > 
> > Code LGTM, Arek, do you spot anything amiss with this?
> 
> Other than the random whitespace changes the patch looks good. Thanks!

I'm sorry, I've transplanted that from code I'm working on and that was
not aware something got caught up.

--
Zbigniew

> 
> Mixing threading and forking is always 'fun' and people rarely think
> about it upfront. I won't be surprised if we will find more things like
> this :-)
> 
> -- 
> Cheers,
> Arek
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

Re: [igt-dev] [PATCH i-g-t] lib/igt_core: Reinitialize print mutex in child process

[Zbigniew Kempczyński]

[-- Attachment #1: Type: text/plain, Size: 1301 bytes --]

On Mon, Sep 28, 2020 at 06:29:20PM +0300, Petri Latvala wrote:
> On Mon, Sep 28, 2020 at 03:15:02PM +0200, Zbigniew Kempczyński wrote:
> > IGT are prone to deadlock in igt_log() in following scenario:
> > 
> > 1. Parent process creates additional thread which for example
> >    is doing endless loop
> > 2. Thread sometimes is logging to console using igt_info().
> >    This locks and unlocks print_mutex.
> > 3. If in the meantime parent process will spawn it can be
> >    spawned with print_mutex locked. If in the child process
> >    it will do igt_info() it will deadlock.
> > 
> > We should reinitialize print_mutex in child process to avoid
> > use inherited value.
> > 
> > Signed-off-by: Zbigniew Kempczyński <zbigniew.kempczynski@intel.com>
> > Cc: Petri Latvala <petri.latvala@intel.com>
> > ---
> 
> Are you able to type up a unit test in lib/tests/ that reproduces this
> deadlock?

I've attached patch which exposes the deadlock. Unfortunately I don't
think the test which produces thousands of log lines is much usable
in the future. In the patch I intentionally increased critical
section time to 1 second to spot the problem. In my opinion patch I've 
sent yesterday should work and I don't know should we add additional
test to verify this scenario in the future.

--
Zbigniew


[-- Attachment #2: 0001-lib-igt_core-Expose-deadlock-in-igt-logging.patch --]
[-- Type: text/x-diff, Size: 4738 bytes --]

From 998d15a647091c5db0ddee8ad52804cbbff2bd7f Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Zbigniew=20Kempczy=C5=84ski?=
 <zbigniew.kempczynski@intel.com>
Date: Tue, 29 Sep 2020 09:43:14 +0200
Subject: [PATCH i-g-t] lib/igt_core: Expose deadlock in igt logging

Just for expose.
---
 lib/igt_core.c         | 13 +++++++--
 tests/Makefile.sources |  1 +
 tests/core_logging.c   | 66 ++++++++++++++++++++++++++++++++++++++++++
 tests/meson.build      |  1 +
 4 files changed, 79 insertions(+), 2 deletions(-)
 create mode 100644 tests/core_logging.c

diff --git a/lib/igt_core.c b/lib/igt_core.c
index cedd8168..c26927cd 100644
--- a/lib/igt_core.c
+++ b/lib/igt_core.c
@@ -2271,8 +2271,12 @@ static void children_exit_handler(int sig)
 		;
 }
 
+static pthread_mutex_t print_mutex = PTHREAD_MUTEX_INITIALIZER;
+
 bool __igt_fork(void)
 {
+	int ret;
+
 	internal_assert(!test_with_subtests || in_subtest,
 			"forking is only allowed in subtests or igt_simple_main\n");
 	internal_assert(!test_child,
@@ -2300,6 +2304,11 @@ bool __igt_fork(void)
 		igt_assert(0);
 	case 0:
 		test_child = true;
+		/* Below fixes issue */
+		//pthread_mutex_init(&print_mutex, NULL);
+		ret = pthread_mutex_trylock(&print_mutex);
+		internal_assert(ret == 0, "Mutex was locked during fork\n");
+		pthread_mutex_unlock(&print_mutex);
 		exit_handler_count = 0;
 		reset_helper_process_list();
 		oom_adjust_for_doom();
@@ -2737,8 +2746,6 @@ void igt_vlog(const char *domain, enum igt_log_level level, const char *format,
 		"NONE"
 	};
 
-	static pthread_mutex_t print_mutex = PTHREAD_MUTEX_INITIALIZER;
-
 	assert(format);
 
 #ifdef __GLIBC__
@@ -2816,6 +2823,8 @@ void igt_vlog(const char *domain, enum igt_log_level level, const char *format,
 		fwrite(line, sizeof(char), strlen(line), file);
 	}
 
+	/* Extend critical section time */
+	sleep(1);
 	pthread_mutex_unlock(&print_mutex);
 
 out:
diff --git a/tests/Makefile.sources b/tests/Makefile.sources
index f32ea9cf..e027cab1 100644
--- a/tests/Makefile.sources
+++ b/tests/Makefile.sources
@@ -19,6 +19,7 @@ TESTS_progs = \
 	core_getstats \
 	core_getversion \
 	core_hotunplug \
+	core_logging \
 	core_setmaster \
 	core_setmaster_vs_auth \
 	debugfs_test \
diff --git a/tests/core_logging.c b/tests/core_logging.c
new file mode 100644
index 00000000..826ec85b
--- /dev/null
+++ b/tests/core_logging.c
@@ -0,0 +1,66 @@
+/*
+ * Copyright © 2020 Intel Corporation
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a
+ * copy of this software and associated documentation files (the "Software"),
+ * to deal in the Software without restriction, including without limitation
+ * the rights to use, copy, modify, merge, publish, distribute, sublicense,
+ * and/or sell copies of the Software, and to permit persons to whom the
+ * Software is furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice (including the next
+ * paragraph) shall be included in all copies or substantial portions of the
+ * Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO EVENT SHALL
+ * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
+ * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
+ * IN THE SOFTWARE.
+ *
+ */
+
+#include "igt.h"
+#include <pthread.h>
+#include <string.h>
+#include <sys/ioctl.h>
+
+IGT_TEST_DESCRIPTION("Tests is IGT logging prone to deadlock");
+
+#define TIMEOUT 10
+
+static void *thread_loop(void *data)
+{
+	int cnt = 0;
+
+	igt_until_timeout(TIMEOUT) {
+		igt_info("... %d\n", cnt++);
+	}
+
+	return NULL;
+}
+
+static void test_deadlock(void)
+{
+	pthread_t thread;
+
+	pthread_create(&thread, NULL, thread_loop, NULL);
+
+	igt_until_timeout(TIMEOUT) {
+		igt_fork(child, 1) {
+			igt_info("child [%d]\n", getpid());
+		}
+		//igt_waitchildren_timeout(1, "deadlock found");
+		igt_waitchildren();
+	}
+
+	pthread_join(thread, NULL);
+}
+
+igt_main
+{
+	igt_subtest("test-deadlock")
+		test_deadlock();
+}
diff --git a/tests/meson.build b/tests/meson.build
index 515f7528..ebdc1aba 100644
--- a/tests/meson.build
+++ b/tests/meson.build
@@ -4,6 +4,7 @@ test_progs = [
 	'core_getstats',
 	'core_getversion',
 	'core_hotunplug',
+	'core_logging',
 	'core_setmaster',
 	'core_setmaster_vs_auth',
 	'debugfs_test',
-- 
2.26.0


[-- Attachment #3: Type: text/plain, Size: 154 bytes --]

_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

[igt-dev] ✗ Fi.CI.BUILD: failure for lib/igt_core: Reinitialize print mutex in child process (rev2)

[Patchwork]

== Series Details ==

Series: lib/igt_core: Reinitialize print mutex in child process (rev2)
URL   : https://patchwork.freedesktop.org/series/82154/
State : failure

== Summary ==

Applying: lib/igt_core: Reinitialize print mutex in child process
Patch failed at 0001 lib/igt_core: Reinitialize print mutex in child process
When you have resolved this problem, run "git am --continue".
If you prefer to skip this patch, run "git am --skip" instead.
To restore the original branch and stop patching, run "git am --abort".


_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

Re: [igt-dev] [PATCH i-g-t] lib/igt_core: Reinitialize print mutex in child process

[Petri Latvala]

On Tue, Sep 29, 2020 at 09:53:05AM +0200, Zbigniew Kempczyński wrote:
> On Mon, Sep 28, 2020 at 06:29:20PM +0300, Petri Latvala wrote:
> > On Mon, Sep 28, 2020 at 03:15:02PM +0200, Zbigniew Kempczyński wrote:
> > > IGT are prone to deadlock in igt_log() in following scenario:
> > > 
> > > 1. Parent process creates additional thread which for example
> > >    is doing endless loop
> > > 2. Thread sometimes is logging to console using igt_info().
> > >    This locks and unlocks print_mutex.
> > > 3. If in the meantime parent process will spawn it can be
> > >    spawned with print_mutex locked. If in the child process
> > >    it will do igt_info() it will deadlock.
> > > 
> > > We should reinitialize print_mutex in child process to avoid
> > > use inherited value.
> > > 
> > > Signed-off-by: Zbigniew Kempczyński <zbigniew.kempczynski@intel.com>
> > > Cc: Petri Latvala <petri.latvala@intel.com>
> > > ---
> > 
> > Are you able to type up a unit test in lib/tests/ that reproduces this
> > deadlock?
> 
> I've attached patch which exposes the deadlock. Unfortunately I don't
> think the test which produces thousands of log lines is much usable
> in the future. In the patch I intentionally increased critical
> section time to 1 second to spot the problem. In my opinion patch I've 
> sent yesterday should work and I don't know should we add additional
> test to verify this scenario in the future.

No no, I meant _lib_/tests/. tests/ contains tests that check whether
kernel works correctly, lib/tests/ contains tests that check whether
IGT infrastructure works correctly.

The structure of the tests in lib/tests can be a bit awkward since you
need to do a lot of the test framework stuff manually, but there
should be plenty of examples.


-- 
Petri Latvala



> 
> --
> Zbigniew
> 

> From 998d15a647091c5db0ddee8ad52804cbbff2bd7f Mon Sep 17 00:00:00 2001
> From: =?UTF-8?q?Zbigniew=20Kempczy=C5=84ski?=
>  <zbigniew.kempczynski@intel.com>
> Date: Tue, 29 Sep 2020 09:43:14 +0200
> Subject: [PATCH i-g-t] lib/igt_core: Expose deadlock in igt logging
> 
> Just for expose.
> ---
>  lib/igt_core.c         | 13 +++++++--
>  tests/Makefile.sources |  1 +
>  tests/core_logging.c   | 66 ++++++++++++++++++++++++++++++++++++++++++
>  tests/meson.build      |  1 +
>  4 files changed, 79 insertions(+), 2 deletions(-)
>  create mode 100644 tests/core_logging.c
> 
> diff --git a/lib/igt_core.c b/lib/igt_core.c
> index cedd8168..c26927cd 100644
> --- a/lib/igt_core.c
> +++ b/lib/igt_core.c
> @@ -2271,8 +2271,12 @@ static void children_exit_handler(int sig)
>  		;
>  }
>  
> +static pthread_mutex_t print_mutex = PTHREAD_MUTEX_INITIALIZER;
> +
>  bool __igt_fork(void)
>  {
> +	int ret;
> +
>  	internal_assert(!test_with_subtests || in_subtest,
>  			"forking is only allowed in subtests or igt_simple_main\n");
>  	internal_assert(!test_child,
> @@ -2300,6 +2304,11 @@ bool __igt_fork(void)
>  		igt_assert(0);
>  	case 0:
>  		test_child = true;
> +		/* Below fixes issue */
> +		//pthread_mutex_init(&print_mutex, NULL);
> +		ret = pthread_mutex_trylock(&print_mutex);
> +		internal_assert(ret == 0, "Mutex was locked during fork\n");
> +		pthread_mutex_unlock(&print_mutex);
>  		exit_handler_count = 0;
>  		reset_helper_process_list();
>  		oom_adjust_for_doom();
> @@ -2737,8 +2746,6 @@ void igt_vlog(const char *domain, enum igt_log_level level, const char *format,
>  		"NONE"
>  	};
>  
> -	static pthread_mutex_t print_mutex = PTHREAD_MUTEX_INITIALIZER;
> -
>  	assert(format);
>  
>  #ifdef __GLIBC__
> @@ -2816,6 +2823,8 @@ void igt_vlog(const char *domain, enum igt_log_level level, const char *format,
>  		fwrite(line, sizeof(char), strlen(line), file);
>  	}
>  
> +	/* Extend critical section time */
> +	sleep(1);
>  	pthread_mutex_unlock(&print_mutex);
>  
>  out:
> diff --git a/tests/Makefile.sources b/tests/Makefile.sources
> index f32ea9cf..e027cab1 100644
> --- a/tests/Makefile.sources
> +++ b/tests/Makefile.sources
> @@ -19,6 +19,7 @@ TESTS_progs = \
>  	core_getstats \
>  	core_getversion \
>  	core_hotunplug \
> +	core_logging \
>  	core_setmaster \
>  	core_setmaster_vs_auth \
>  	debugfs_test \
> diff --git a/tests/core_logging.c b/tests/core_logging.c
> new file mode 100644
> index 00000000..826ec85b
> --- /dev/null
> +++ b/tests/core_logging.c
> @@ -0,0 +1,66 @@
> +/*
> + * Copyright © 2020 Intel Corporation
> + *
> + * Permission is hereby granted, free of charge, to any person obtaining a
> + * copy of this software and associated documentation files (the "Software"),
> + * to deal in the Software without restriction, including without limitation
> + * the rights to use, copy, modify, merge, publish, distribute, sublicense,
> + * and/or sell copies of the Software, and to permit persons to whom the
> + * Software is furnished to do so, subject to the following conditions:
> + *
> + * The above copyright notice and this permission notice (including the next
> + * paragraph) shall be included in all copies or substantial portions of the
> + * Software.
> + *
> + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
> + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
> + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.  IN NO EVENT SHALL
> + * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
> + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
> + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
> + * IN THE SOFTWARE.
> + *
> + */
> +
> +#include "igt.h"
> +#include <pthread.h>
> +#include <string.h>
> +#include <sys/ioctl.h>
> +
> +IGT_TEST_DESCRIPTION("Tests is IGT logging prone to deadlock");
> +
> +#define TIMEOUT 10
> +
> +static void *thread_loop(void *data)
> +{
> +	int cnt = 0;
> +
> +	igt_until_timeout(TIMEOUT) {
> +		igt_info("... %d\n", cnt++);
> +	}
> +
> +	return NULL;
> +}
> +
> +static void test_deadlock(void)
> +{
> +	pthread_t thread;
> +
> +	pthread_create(&thread, NULL, thread_loop, NULL);
> +
> +	igt_until_timeout(TIMEOUT) {
> +		igt_fork(child, 1) {
> +			igt_info("child [%d]\n", getpid());
> +		}
> +		//igt_waitchildren_timeout(1, "deadlock found");
> +		igt_waitchildren();
> +	}
> +
> +	pthread_join(thread, NULL);
> +}
> +
> +igt_main
> +{
> +	igt_subtest("test-deadlock")
> +		test_deadlock();
> +}
> diff --git a/tests/meson.build b/tests/meson.build
> index 515f7528..ebdc1aba 100644
> --- a/tests/meson.build
> +++ b/tests/meson.build
> @@ -4,6 +4,7 @@ test_progs = [
>  	'core_getstats',
>  	'core_getversion',
>  	'core_hotunplug',
> +	'core_logging',
>  	'core_setmaster',
>  	'core_setmaster_vs_auth',
>  	'debugfs_test',
> -- 
> 2.26.0
> 

_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

Re: [igt-dev] [PATCH i-g-t] lib/igt_core: Reinitialize print mutex in child process

[Zbigniew Kempczyński]

On Tue, Sep 29, 2020 at 12:24:59PM +0300, Petri Latvala wrote:
> On Tue, Sep 29, 2020 at 09:53:05AM +0200, Zbigniew Kempczyński wrote:
> > On Mon, Sep 28, 2020 at 06:29:20PM +0300, Petri Latvala wrote:
> > > On Mon, Sep 28, 2020 at 03:15:02PM +0200, Zbigniew Kempczyński wrote:
> > > > IGT are prone to deadlock in igt_log() in following scenario:
> > > > 
> > > > 1. Parent process creates additional thread which for example
> > > >    is doing endless loop
> > > > 2. Thread sometimes is logging to console using igt_info().
> > > >    This locks and unlocks print_mutex.
> > > > 3. If in the meantime parent process will spawn it can be
> > > >    spawned with print_mutex locked. If in the child process
> > > >    it will do igt_info() it will deadlock.
> > > > 
> > > > We should reinitialize print_mutex in child process to avoid
> > > > use inherited value.
> > > > 
> > > > Signed-off-by: Zbigniew Kempczyński <zbigniew.kempczynski@intel.com>
> > > > Cc: Petri Latvala <petri.latvala@intel.com>
> > > > ---
> > > 
> > > Are you able to type up a unit test in lib/tests/ that reproduces this
> > > deadlock?
> > 
> > I've attached patch which exposes the deadlock. Unfortunately I don't
> > think the test which produces thousands of log lines is much usable
> > in the future. In the patch I intentionally increased critical
> > section time to 1 second to spot the problem. In my opinion patch I've 
> > sent yesterday should work and I don't know should we add additional
> > test to verify this scenario in the future.
> 
> No no, I meant _lib_/tests/. tests/ contains tests that check whether
> kernel works correctly, lib/tests/ contains tests that check whether
> IGT infrastructure works correctly.
> 
> The structure of the tests in lib/tests can be a bit awkward since you
> need to do a lot of the test framework stuff manually, but there
> should be plenty of examples.
> 

I don't have currently much time to work on test version you likely 
expect. I think we know what's the root cause of not proper IGT logging
behavior in multithreading/multiprocessing environmant and fix is quite
obvious. I don't think we need test which will test that lock verification.
Especially to reproduce I have to do atomic bomb of igt_info() which 
completely dominate in output and produces have thousaunds of lines before
deadlock occurs.

Anyway, I needed such logging during my development so in final version
of patches they will disappear. So decision of incorporation of my fix
or not I left to you.

--
Zbigniew 
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev

Re: [igt-dev] [PATCH i-g-t] lib/igt_core: Reinitialize print mutex in child process

[Petri Latvala]

On Tue, Sep 29, 2020 at 12:19:14PM +0200, Zbigniew Kempczyński wrote:
> On Tue, Sep 29, 2020 at 12:24:59PM +0300, Petri Latvala wrote:
> > On Tue, Sep 29, 2020 at 09:53:05AM +0200, Zbigniew Kempczyński wrote:
> > > On Mon, Sep 28, 2020 at 06:29:20PM +0300, Petri Latvala wrote:
> > > > On Mon, Sep 28, 2020 at 03:15:02PM +0200, Zbigniew Kempczyński wrote:
> > > > > IGT are prone to deadlock in igt_log() in following scenario:
> > > > > 
> > > > > 1. Parent process creates additional thread which for example
> > > > >    is doing endless loop
> > > > > 2. Thread sometimes is logging to console using igt_info().
> > > > >    This locks and unlocks print_mutex.
> > > > > 3. If in the meantime parent process will spawn it can be
> > > > >    spawned with print_mutex locked. If in the child process
> > > > >    it will do igt_info() it will deadlock.
> > > > > 
> > > > > We should reinitialize print_mutex in child process to avoid
> > > > > use inherited value.
> > > > > 
> > > > > Signed-off-by: Zbigniew Kempczyński <zbigniew.kempczynski@intel.com>
> > > > > Cc: Petri Latvala <petri.latvala@intel.com>
> > > > > ---
> > > > 
> > > > Are you able to type up a unit test in lib/tests/ that reproduces this
> > > > deadlock?
> > > 
> > > I've attached patch which exposes the deadlock. Unfortunately I don't
> > > think the test which produces thousands of log lines is much usable
> > > in the future. In the patch I intentionally increased critical
> > > section time to 1 second to spot the problem. In my opinion patch I've 
> > > sent yesterday should work and I don't know should we add additional
> > > test to verify this scenario in the future.
> > 
> > No no, I meant _lib_/tests/. tests/ contains tests that check whether
> > kernel works correctly, lib/tests/ contains tests that check whether
> > IGT infrastructure works correctly.
> > 
> > The structure of the tests in lib/tests can be a bit awkward since you
> > need to do a lot of the test framework stuff manually, but there
> > should be plenty of examples.
> > 
> 
> I don't have currently much time to work on test version you likely 
> expect. I think we know what's the root cause of not proper IGT logging
> behavior in multithreading/multiprocessing environmant and fix is quite
> obvious. I don't think we need test which will test that lock verification.
> Especially to reproduce I have to do atomic bomb of igt_info() which 
> completely dominate in output and produces have thousaunds of lines before
> deadlock occurs.
> 
> Anyway, I needed such logging during my development so in final version
> of patches they will disappear. So decision of incorporation of my fix
> or not I left to you.

Yeah, fair enough.

Do you have a version without the spurious whitespace changes? Slap a

Reviewed-by: Petri Latvala <petri.latvala@intel.com>

on it.
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev