QA » openQA Project

The first query likely corresponds to the update via DBIx in OpenQA::Schema::Result::Assets::refresh_size which is invoked when tracking/cleaning assets. The second query points to OpenQA::Schema::Result::Jobs::extract_group_args_from_settings which is invoked when scheduling the product (and thus happening within an explicit transaction but using the default isolation level). So asset tracking and product scheduling are interfering with each other.

After re-scheduling the product the jobs were created as expected. The deadlock likely only occurs in a very specific situation (the asset tracking needs to be at a certain point and the scheduling needs to be at a certain point). That makes it hard to reproduce.

Looks like this isn't the only time when a deadlock occurred:

ariel:/var/lib/pgsql/data/log # grep deadlock *.log
postgresql-2022-11-09_000000.log:2022-11-09 16:55:50.979 UTC openqa geekotest [8975]ERROR:  deadlock detected
postgresql-2022-11-14_000000.log:2022-11-14 17:14:51.019 UTC openqa geekotest [31118]ERROR:  deadlock detected
postgresql-2022-11-19_000000.log:2022-11-19 05:21:07.088 UTC openqa geekotest [16976]ERROR:  deadlock detected
postgresql-2022-11-20_000000.log:2022-11-20 01:59:09.753 UTC openqa geekotest [6320]ERROR:  deadlock detected
postgresql-2022-11-23_000000.log:2022-11-23 00:40:32.766 UTC openqa geekotest [26448]ERROR:  deadlock detected
postgresql-2022-11-23_000000.log:2022-11-23 00:40:33.770 UTC openqa geekotest [26494]ERROR:  deadlock detected
postgresql-2022-11-23_000000.log:2022-11-23 01:09:39.771 UTC openqa geekotest [3080]ERROR:  deadlock detected

The other deadlocks are also either about reading a row from job groups or about updating the size of an asset.

The log looks like this:

2022-11-23 00:40:32.766 UTC openqa geekotest [26448]ERROR:  deadlock detected
2022-11-23 00:40:32.766 UTC openqa geekotest [26448]DETAIL:  Process 26448 waits for ShareLock on transaction 166381112; blocked by process 26494.
        Process 26494 waits for ExclusiveLock on tuple (135,64) of relation 16400 of database 16401; blocked by process 26466.
        Process 26466 waits for ShareLock on transaction 166381053; blocked by process 26448.
        Process 26448: UPDATE assets SET size = $1, t_updated = $2 WHERE id = $3
        Process 26494: UPDATE assets SET size = $1, t_updated = $2 WHERE id = $3
        Process 26466: UPDATE assets SET size = $1, t_updated = $2 WHERE id = $3
2022-11-23 00:40:32.766 UTC openqa geekotest [26448]HINT:  See server log for query details.
2022-11-23 00:40:32.766 UTC openqa geekotest [26448]CONTEXT:  while updating tuple (135,67) in relation "assets"
2022-11-23 00:40:32.766 UTC openqa geekotest [26448]STATEMENT:  UPDATE assets SET size = $1, t_updated = $2 WHERE id = $3
2022-11-23 00:40:32.795 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.795 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.801 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.801 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.808 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.808 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.813 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.813 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.817 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.817 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.822 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.822 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.827 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.827 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.834 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.834 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.839 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.839 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.844 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.844 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.848 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.848 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.853 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.853 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.859 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.859 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.864 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.864 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.869 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.869 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.873 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.873 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.879 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.879 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.890 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.890 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.912 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.912 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.919 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.919 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.924 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.924 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.928 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.928 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.932 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:32.932 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:32.937 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
…
2022-11-23 00:40:33.065 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:33.065 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:33.072 UTC openqa geekotest [26448]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 00:40:33.072 UTC openqa geekotest [26448]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 00:40:33.770 UTC openqa geekotest [26494]ERROR:  deadlock detected
2022-11-23 00:40:33.770 UTC openqa geekotest [26494]DETAIL:  Process 26494 waits for ShareLock on transaction 166381074; blocked by process 26466.
        Process 26466 waits for ShareLock on transaction 166381112; blocked by process 26494.
        Process 26494: UPDATE assets SET size = $1, t_updated = $2 WHERE id = $3
        Process 26466: UPDATE assets SET size = $1, t_updated = $2 WHERE id = $3
2022-11-23 00:40:33.770 UTC openqa geekotest [26494]HINT:  See server log for query details.
2022-11-23 00:40:33.770 UTC openqa geekotest [26494]CONTEXT:  while updating tuple (135,64) in relation "assets"
2022-11-23 00:40:33.770 UTC openqa geekotest [26494]STATEMENT:  UPDATE assets SET size = $1, t_updated = $2 WHERE id = $3
2022-11-23 01:09:39.771 UTC openqa geekotest [3080]ERROR:  deadlock detected
2022-11-23 01:09:39.771 UTC openqa geekotest [3080]DETAIL:  Process 3080 waits for ShareLock on transaction 166511492; blocked by process 3132.
        Process 3132 waits for ShareLock on transaction 166511322; blocked by process 3080.
        Process 3080: UPDATE assets SET size = $1, t_updated = $2 WHERE id = $3
        Process 3132: UPDATE assets SET size = $1, t_updated = $2 WHERE id = $3
2022-11-23 01:09:39.771 UTC openqa geekotest [3080]HINT:  See server log for query details.
2022-11-23 01:09:39.771 UTC openqa geekotest [3080]CONTEXT:  while updating tuple (144,69) in relation "assets"
2022-11-23 01:09:39.771 UTC openqa geekotest [3080]STATEMENT:  UPDATE assets SET size = $1, t_updated = $2 WHERE id = $3
2022-11-23 01:09:39.784 UTC openqa geekotest [3080]ERROR:  current transaction is aborted, commands ignored until end of transaction block
2022-11-23 01:09:39.784 UTC openqa geekotest [3080]STATEMENT:  SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = $1 )
2022-11-23 01:09:46.768 UTC openqa geekotest [3188]LOG:  duration: 7578.684 ms  execute <unnamed>:         INSERT INTO assets (type, name, t_created, t_updated)
                            VALUES ($1,    $2,    now(),     now()    ) ON CONFLICT DO NOTHING

2022-11-23 01:09:46.768 UTC openqa geekotest [3188]DETAIL:  parameters: $1 = 'repo', $2 = 'openSUSE-Tumbleweed-oss-i586-x86_64-Snapshot20221122-source'
2022-11-23 01:09:46.768 UTC openqa geekotest [3168]LOG:  duration: 7809.833 ms  execute <unnamed>: UPDATE assets SET size = $1, t_updated = $2 WHERE id = $3
2022-11-23 01:09:46.768 UTC openqa geekotest [3168]DETAIL:  parameters: $1 = '499788508', $2 = '2022-11-23 01:09:38', $3 = '66765244'

I fail to see how reading job groups would interfere with updating assets. Maybe this is just the query that's executed when the transaction is aborted. So I had a look what else we do in that transaction. It turns out that within the scheduling transaction we run register_assets_from_settings which runs ensure_size which runs ensure_size which eventually also runs refresh_size. So we update the size column of assets while tracking assets and while scheduling products. That could be our deadlock/conflict.

By the way, when doing

$schema->txn_do(sub {  # explicit transaction via first database connection
        note 'update 1';
        $schema->resultset('Assets')->first->update({size => 50});
        note 'update 2';
        $schema2->resultset('Assets')->first->update({size => 49});  # an update via a different database connection while the explicit transaction has not been committed
        note 'done 1';
    });
    note 'done 2';

that creates a deadlock. I get only the first two lines logged. However, in my tests it gets just stuck without running into the "deadlock detected" error. I just get the following log messages:

2022-11-23 15:27:36.136 CET openqa_test martchus [31691]LOG:  process 31691 still waiting for ShareLock on transaction 996 after 1.052 ms
2022-11-23 15:27:36.136 CET openqa_test martchus [31691]DETAIL:  Process holding the lock: 31688. Wait queue: 31691.
2022-11-23 15:27:36.136 CET openqa_test martchus [31691]CONTEXT:  while updating tuple (0,1) in relation "assets"
2022-11-23 15:27:36.136 CET openqa_test martchus [31691]STATEMENT:  UPDATE assets SET size = $1, t_updated = $2 WHERE ( id = $3 )
2022-11-23 15:27:46.128 CET openqa_test martchus [31691]LOG:  process 31691 still waiting for ShareLock on transaction 996 after 9993.372 ms
2022-11-23 15:27:46.128 CET openqa_test martchus [31691]DETAIL:  Process holding the lock: 31688. Wait queue: 31691.
2022-11-23 15:27:46.128 CET openqa_test martchus [31691]CONTEXT:  while updating tuple (0,1) in relation "assets"
2022-11-23 15:27:46.128 CET openqa_test martchus [31691]STATEMENT:  UPDATE assets SET size = $1, t_updated = $2 WHERE ( id = $3 )

EDIT: That's actually not a good example. If I start the 2nd update in a sub process and wait in the main process until it terminated it works just fine.

PostgreSQL docs about transaction isolation that should be relevant here: https://www.postgresql.org/docs/current/transaction-iso.html

As expected this is a tricky one. I do have suspicions though, the deadlock itself is undoubtedly on this line. And the root cause will have something to do with this transaction, which has a very wide scope. This kind of deadlock usually happens with an UPDATE ordering problem, where two transactions try to update multiple rows of a table, and each gets the lock on a different row at the same time, deadlocking each other. Which leads me to believe that this line could be at fault. The usual fix for a problem like this would be to do a SELECT ... FOR UPDATE on all the rows you plan to update before doing it. Which is not so easy with the convoluted DBIx::Class code involved here.

We did have a few more cases recently btw.

postgresql-2022-11-24_000000.log:2022-11-24 09:35:05.878 UTC openqa geekotest [32110]ERROR:  deadlock detected
postgresql-2022-11-24_000000.log:2022-11-24 09:35:06.881 UTC openqa geekotest [32298]ERROR:  deadlock detected
postgresql-2022-11-27_000000.log:2022-11-27 04:31:55.788 UTC openqa geekotest [10404]ERROR:  deadlock detected
postgresql-2022-12-01_000000.log:2022-12-01 03:46:12.925 UTC openqa geekotest [7300]ERROR:  deadlock detected
postgresql-2022-12-01_000000.log:2022-12-01 22:08:49.641 UTC openqa geekotest [26387]ERROR:  deadlock detected
postgresql-2022-12-01_000000.log:2022-12-01 23:57:27.173 UTC openqa geekotest [25245]ERROR:  deadlock detected
postgresql-2022-12-06_000000.log:2022-12-06 01:38:27.615 UTC openqa geekotest [10906]ERROR:  deadlock detected

Added a PR to rule out one of two spots where the UPDATE query causing the deadlock could have originated: https://github.com/os-autoinst/openQA/pull/4943

In case someone else has to work on this again, this article has a good explanation for UPDATE ordering deadlocks. I suspect that we are dealing with a variant of that.

Think i know how to fix it, simply making sure that all processes handle assets in the same order here should do the trick. The exact order doesn't matter, it just needs to be consistent between processes. Preparing a patch now.

Second PR with a possible ordering fix: https://github.com/os-autoinst/openQA/pull/4952

kraih wrote:

Lets wait a few days and keep an eye on the logs.

[2022-12-09T10:01:48.096130Z] [warn] [pid:21728] Unable to incomplete/duplicate or reschedule jobs abandoned by worker 498: DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD::Pg::st execute failed: ERROR:  deadlock detected
DETAIL:  Process 21755 waits for ShareLock on transaction 244660614; blocked by process 22220.
Process 22220 waits for ShareLock on transaction 244660621; blocked by process 21755.
HINT:  See server log for query details.
CONTEXT:  while updating tuple (5964,52) in relation "jobs" [for Statement "UPDATE jobs SET result = ?, t_updated = ? WHERE id = ?" with ParamValues: 1='parallel_failed', 2='2022-12-09 10:01:47', 3='2943098'] at /usr/share/openqa/script/../lib/OpenQA/Schema/Result/Jobs.pm line 1779

[2022-12-09T06:21:08.420239Z] [warn] [pid:6924] Unable to incomplete/duplicate or reschedule jobs abandoned by worker 511: DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD::Pg::st execute failed: ERROR:  deadlock detected
DETAIL:  Process 6931 waits for ShareLock on transaction 243609936; blocked by process 5779.
Process 5779 waits for ShareLock on transaction 243609932; blocked by process 6931.
HINT:  See server log for query details.
CONTEXT:  while updating tuple (3166,30) in relation "jobs" [for Statement "UPDATE jobs SET result = ?, t_updated = ? WHERE id = ?" with ParamValues: 1='parallel_failed', 2='2022-12-09 06:21:07', 3='2939946'] at /usr/share/openqa/script/../lib/OpenQA/Schema/Result/Jobs.pm line 1779
[2022-12-09T06:54:32.672698Z] [warn] [pid:28682] Unable to incomplete/duplicate or reschedule jobs abandoned by worker 519: DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD::Pg::st execute failed: ERROR:  deadlock detected
DETAIL:  Process 28685 waits for ShareLock on transaction 243819997; blocked by process 30309.
Process 30309 waits for ShareLock on transaction 243819999; blocked by process 28685.
HINT:  See server log for query details.
CONTEXT:  while updating tuple (2930,111) in relation "jobs" [for Statement "UPDATE jobs SET result = ?, t_updated = ? WHERE id = ?" with ParamValues: 1='parallel_failed', 2='2022-12-09 06:54:31', 3='2941928'] at /usr/share/openqa/script/../lib/OpenQA/Schema/Result/Jobs.pm line 1779

cdywan wrote:

[2022-12-09T10:01:48.096130Z] [warn] [pid:21728] Unable to incomplete/duplicate or reschedule jobs abandoned by worker 498: DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD::Pg::st execute failed: ERROR:  deadlock detected
DETAIL:  Process 21755 waits for ShareLock on transaction 244660614; blocked by process 22220.
Process 22220 waits for ShareLock on transaction 244660621; blocked by process 21755.
HINT:  See server log for query details.
CONTEXT:  while updating tuple (5964,52) in relation "jobs" [for Statement "UPDATE jobs SET result = ?, t_updated = ? WHERE id = ?" with ParamValues: 1='parallel_failed', 2='2022-12-09 10:01:47', 3='2943098'] at /usr/share/openqa/script/../lib/OpenQA/Schema/Result/Jobs.pm line 1779

Ah, you noticed it too. That's a different deadlock, and i've opened a new ticket for it: #121777

Can this: https://openqa.suse.de/minion/jobs?id=6073000 be related?

  - error_message: |
      DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD::Pg::st execute failed: ERROR:  deadlock detected
      DETAIL:  Process 11392 waits for ShareLock on transaction 1441261351; blocked by process 20591.
      Process 20591 waits for ShareLock on transaction 1441213509; blocked by process 11392.
      HINT:  See server log for query details.
      CONTEXT:  while locking tuple (238,55) in relation "assets" [for Statement "SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = ? AND me.type = ? ) ) FOR UPDATE" with ParamValues: 1='windows-10-x86_64-21H2@windows_bios_boot.qcow2', 2='hdd'] at /usr/share/openqa/script/../lib/OpenQA/Schema/Result/Jobs.pm line 1509
    job_name: sles4sap_remote_desktop_windows_client_ppc64le
  - error_message: |
      DBIx::Class::Storage::DBI::_dbh_execute(): DBI Exception: DBD::Pg::st execute failed: ERROR:  current transaction is aborted, commands ignored until end of transaction block [for Statement "SELECT me.id, me.name, me.parent_id, me.size_limit_gb, me.exclusively_kept_asset_size, me.keep_logs_in_days, me.keep_important_logs_in_days, me.keep_results_in_days, me.keep_important_results_in_days, me.default_priority, me.sort_order, me.description, me.template, me.build_version_sort, me.carry_over_bugrefs, me.t_created, me.t_updated FROM job_groups me WHERE ( me.id = ? )" with ParamValues: 1='146'] at /usr/share/openqa/script/../lib/OpenQA/Schema/Result/Jobs.pm line 576
    job_name: SAPHanaSR_ScaleUp_PerfOpt_supportserver
...

On O3 there have been no new cases. So it looks like at least the assets specific deadlock has been resolved.

jbaier_cz wrote:

Can this: https://openqa.suse.de/minion/jobs?id=6073000 be related?

Yes it can is. This is what i see in the PostgreSQL logs:

2022-12-15 22:30:58.389 CET openqa geekotest [11392]ERROR:  deadlock detected
2022-12-15 22:30:58.389 CET openqa geekotest [11392]DETAIL:  Process 11392 waits for ShareLock on transaction 1441261351; blocked by process 20591.
        Process 20591 waits for ShareLock on transaction 1441213509; blocked by process 11392.
        Process 11392: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = $1 AND me.type = $2 ) ) FOR UPDATE
        Process 20591: SELECT me.id, me.type, me.name, me.size, me.checksum, me.last_use_job_id, me.fixed, me.t_created, me.t_updated FROM assets me WHERE ( ( me.name = $1 AND me.type = $2 ) ) FOR UPDATE

Which seems to come from here, triggered by the schedule_iso task. And from there it reaches the same loop that previously caused the update deadlock. Problem is the huge transaction block spanning all jobs being created. There is probably no way around splitting it up. At least the deadlock from this code path is a lot more rare, so this is not as urgent.

To sum it up: I think the problem here is that the big transaction loops over the same assets multiple times, for different jobs, which means the order from the inner loop cannot prevent the deadlock. One solution would be to split up the big transaction, or maybe the update of the assets table can be skipped since this is about creating jobs.

Putting it back in the queue for now, in case someone else would like to give it a shot. Untangling the big transaction is definitely a bit tricky, and there is no reproducer to make sure you've actually fixed it. If necessary i'll pick it up again later.

Problem is the huge transaction block spanning all jobs being created. There is probably no way around splitting it up.

Unfortunately this is in a transaction on purpose. The scheduler code should only see all those newly created jobs or none and in case of an error we don't want a half-scheduled product.

or maybe the update of the assets table can be skipped since this is about creating jobs.

That might be the simplest solution. However, this would likely break the check whether an asset exists that's done when restarting (see 50b986e957a4f2c30d94c8499d43700746ae6c42). At least that would be the case when the asset size hasn't been otherwise determined yet.

mkittler wrote:

Unfortunately this is in a transaction on purpose. The scheduler code should only see all those newly created jobs or none and in case of an error we don't want a half-scheduled product.

I feared this would be the case. Really too bad, was hoping we could switch to smaller transactions everywhere and make the code easier to follow.

Here's a follow-up for my previous PR (which was incomplete): https://github.com/os-autoinst/openQA/pull/4981

That will hopefully fix the remaining cases we've still seen on OSD.

I haven't found any further occurrences via sudo -u postgres bash -c 'grep "deadlock detected" /var/lib/pgsql/data/log/postgresql-2023-01-*' on o3 and OSD after my PR has been merged. I'll keep the ticket in feedback to check again next week.

Still no deadlocks being looked. Let's wait before resolving this ticket at least until Wednesday (when I'll check again).