Job qui ne se termine pas à cause d'un Select suspendu (?)

Ca fait un moment que nous avons, de temps en temps, des blocages dont l'origine nous échappe. :aie:
Ce matin nous avons eu à nouveau l'évènement : un job planifié avec une récurrence de 1 minute (en permanence) se met en mode SUSPENDED de manière infinie.
Nous avons du "killer" la session. :aie:

Bien sûr:weird:, nous avons vérifié, le job en question ne consomme aucune ressource réseau du fait de son code.
De plus c'est le seul à être bloqué ce matin parmi une joyeuse collection de jobs.
Et comme on a pris notre temps pour tout ça on a tué la tâche vers 11h alors qu'elle était dans cet état depuis 7h du mat.
La session n'en bloquait pas encore d'autres malgré ses verrous, mais l'expérience nous a montré qu'il fallait ne pas trop tarder quand même :aie:

Voici ce que nous avons collecté à propos de cette session :

sys.dm_os_waiting_tasks

waiting_task_address	0x000000CE9B6F24E8
session_id	163
exec_context_id	0
wait_duration_ms	535
wait_type	ASYNC_NETWORK_IO
resource_address	0x000000BF8AEC8CA0
blocking_task_address	NULL
blocking_session_id	NULL
blocking_exec_context_id	NULL
resource_description

sys.dm_tran_locks

resource_type	DATABASE	DATABASE	DATABASE
resource_subtype
resource_database_id	9	35	45
resource_description
resource_associated_entity_id	0	0	0
resource_lock_partition	6	6	6
request_mode	S	S	S
request_type	LOCK	LOCK	LOCK
request_status	GRANT	GRANT	GRANT
request_reference_count	1	1	1
request_lifetime	0	0	0
request_session_id	163	163	163
request_exec_context_id	0	0	0
request_request_id	0	0	0
request_owner_type	SHARED_TRANSACTION_WORKSPACE	SHARED_TRANSACTION_WORKSPACE	SHARED_TRANSACTION_WORKSPACE
request_owner_id	0	0	0
request_owner_guid	00000000-0000-0000-0000-000000000000	00000000-0000-0000-0000-000000000000	00000000-0000-0000-0000-000000000000
request_owner_lockspace_id	0x000000C1AB851130:0:0	0x000000C1AB851130:0:0	0x000000C1AB851130:0:0
lock_owner_address	0x00000102FD945500	0x000000B4213A7C80	0x000000CD4D1B54C0

sys.dm_exec_connections

session_id	163
most_recent_session_id	163
connect_time	2018-04-1907:13:30.083
net_transport	Sharedmemory
protocol_type	TSQL
protocol_version	1946157060
endpoint_id	2
encrypt_option	FALSE
auth_scheme	NTLM
node_affinity	0
num_reads	11
num_writes	70
last_read	2018-04-1907:13:30.087
last_write	2018-04-1907:15:37.340
net_packet_size	8192
client_net_address	<localmachine>
client_tcp_port	NULL
local_net_address	NULL
local_tcp_port	NULL
connection_id	9F010793-BE3C-42CE-BF2C-027134DA4CD7
parent_connection_id	NULL
most_recent_sql_handle	0x0300090020AE4364D5E9AC0005A8000001000000000000000000000000000000000000000000000000000000

sys.dm_exec_requests

session_id	163
request_id	0
start_time	2018-04-1907:13:30.090
status	suspended
command	SELECT
sql_handle	0x0300090020AE4364D5E9AC0005A8000001000000000000000000000000000000000000000000000000000000
statement_start_offset	46134
statement_end_offset	46284
plan_handle	0x0500090020AE4364501F87631F01000001000000000000000000000000000000000000000000000000000000
database_id	9
user_id	1
connection_id	9F010793-BE3C-42CE-BF2C-027134DA4CD7
blocking_session_id	0
wait_type	ASYNC_NETWORK_IO
wait_time	533
last_wait_type	ASYNC_NETWORK_IO
wait_resource
open_transaction_count	0
open_resultset_count	1
transaction_id	0
context_info	0x
percent_complete	0.0
estimated_completion_time	0
cpu_time	140654
total_elapsed_time	11105321
scheduler_id	6
task_address	0x000000CE9B6F24E8
reads	106971
writes	112
logical_reads	2664242
text_size	1024
language	Français
date_format	dmy
date_first	1
quoted_identifier	1
arithabort	0
ansi_null_dflt_on	1
ansi_defaults	0
ansi_warnings	1
ansi_padding	1
ansi_nulls	1
concat_null_yields_null	1
transaction_isolation_level	2
lock_timeout	-1
deadlock_priority	0
row_count	1
prev_error	0
nest_level	7
granted_query_memory	0
executing_managed_code	0
group_id	2
query_hash	NULL
query_plan_hash	NULL
statement_sql_handle	NULL
statement_context_id	NULL
dop	1
parallel_worker_count	NULL
external_script_request_id	NULL

sys.dm_os_workers

worker_address	0x00000113DF40C160
status	0
is_preemptive	0
is_fiber	0
is_sick	0
is_in_cc_exception	0
is_fatal_exception	0
is_inside_catch	0
is_in_polling_io_completion_routine	0
context_switch_count	7164858
pending_io_count	11109
pending_io_byte_count	0
pending_io_byte_average	0
wait_started_ms_ticks	2924418089
wait_resumed_ms_ticks	2924418089
task_bound_ms_ticks	2913313301
worker_created_ms_ticks	2890703855
exception_num	208
exception_severity	16
exception_address	0x00007FF846BBE030
affinity	64
state	SUSPENDED
start_quantum	2924418585
end_quantum	2924418589
last_wait_type	ASYNC_NETWORK_IO
return_code	258
quantum_used	478182
max_quantum	72
boost_count	1000
tasks_processed_count	64883
fiber_address	NULL
task_address	0x000000CE9B6F24E8
memory_object_address	0x00000113DF40C040
thread_address	0x000000E945570FA0
signal_worker_address	0x0000011BC9478160
scheduler_address	0x000000CEA23E0040
processor_group	0

Si vous avez des idées, nous sommes prenneurs.

Ces information n'ont aucun intérêt sans le contexte. En effet une attente est généralement liée à un blocage et il aurait fallu identifier qui bloque qui dans la vue sys.dm_exec_requests.

Lisez l'article que j'ai écrit à ce sujet :
https://blog.developpez.com/sqlpro/p...stance-bloquee

A +

@SQLpro Merci d'avoir pris le temps de répondre.

Pour moi c'est pas pertinent.
Maintenant il est vrai que lorsqu'on demande de l'aide et qu'une personne vous indique que ce qu'on fourni n'est pas utile et qu'il eut fallu carrément autre chose, soit on s'incline devant la sommation soit on peut fournir l'information salvatrice.
Voici donc le complément d'information qui, je l'espère vivement, vous permettra de nous inonder de votre lumière.

En attendant je vais consulter de plus près votre prose qui est très généralement de bonne facture.

session_id	163
request_id	0
start_time	2018-04-1907:13:30.090
status	suspended
command	SELECT
sql_handle	0x0300090020AE4364D5E9AC0005A8000001000000000000000000000000000000000000000000000000000000
statement_start_offset	46134
statement_end_offset	46284
plan_handle	0x0500090020AE4364501F87631F01000001000000000000000000000000000000000000000000000000000000
database_id	9
user_id	1
connection_id	9F010793-BE3C-42CE-BF2C-027134DA4CD7
blocking_session_id	0
wait_type	ASYNC_NETWORK_IO
wait_time	1105
last_wait_type	ASYNC_NETWORK_IO
wait_resource
open_transaction_count	0
open_resultset_count	1
transaction_id	0
context_info	0x
percent_complete	0.0
estimated_completion_time	0
cpu_time	140650
total_elapsed_time	10087465
scheduler_id	6
task_address	0x000000CE9B6F24E8
reads	106971
writes	112
logical_reads	2664242
text_size	1024
language	Français
date_format	dmy
date_first	1
quoted_identifier	1
arithabort	0
ansi_null_dflt_on	1
ansi_defaults	0
ansi_warnings	1
ansi_padding	1
ansi_nulls	1
concat_null_yields_null	1
transaction_isolation_level	2
lock_timeout	-1
deadlock_priority	0
row_count	1
prev_error	0
nest_level	7
granted_query_memory	0
executing_managed_code	0
group_id	2
query_hash	NULL
query_plan_hash	NULL
statement_sql_handle	NULL
statement_context_id	NULL
dop	1
parallel_worker_count	NULL
external_script_request_id	NULL

Bonjour,

Il serait intéressant de connaitre la requête en cours d’exécution au moment de l’événement.

Car visiblement, la tache est en attente du réseau, et le temps d'attente est de 300ms dans votre premier post, 1100 ms dans le second. La tache ne semble donc pas réellement bloquée, mais juste fortement ralentie par un réseau apparemment poussif.

Bien vu pour la remarque des temps d'attentes.

En fait l'ensemble de la collecte est faite par un script.
Le déclenchement de ce script est manuel.
La vue sys.dm_exec_requests (2ieme post) est collectée avant les autres :calim2:

Pour ce qui est de la requête elle même je n'ai pas le droit d'exposer du code sur internet.
Ce serait plus simple mais je n'ai pas le droit.

donc :
Oui, il s'agit de procédure qui en appelle d'autres.
Non le code n'appelle rien qui soit explicitement hors instance.

Précisions importantes :
- Le job modifie des données qui sont en réplication transactionnelle dont l'éditeur et l'abonné sont dans la même instance alors que le distributeur est sur un serveur distant (toutes les instances sont en 2016)
- nous avons beaucoup de bases par instance.
- Le bout de code désigné comme bloquant :
--n'inclus pas de SELECT mais des SET
--fait parti d'une procédure systématique dans nos développement.
--fait partie d'une manipulation de chaine pour créer du SQL dynamique
--est pratiquement la dernière instruction de la procedure
--devait construire le message de bonne finalisation de l'exécution
- sur l'ensemble du code, aucun ordre appelle une ressource externe à l'instance
- grosso modo c'est la 3ieme apparition de ce phénomène en 1 an. Ce qui est peu pour un job permanent.
--lors des incidents précédents le blocage avait perduré plusieurs jours et fini par bloquer d'autres demandes.
- On a créé une alerte sur le niveau de sévérité 16 qui envoi un mail. Pas de mail sur la période.

Il est possible/probable qu'on ne capture pas les bonnes informations.
Je cherche d'ailleurs à savoir comment récupérer les valeurs des variables de sessions d'une session précise.

Citation:

---

Envoyé par Tagginfo

- nous avons beaucoup de bases par instance.

---

Combien ? Il n'est pas souhaitable de dépasser la centaine...

Citation:

---

- Le bout de code désigné comme bloquant :
--n'inclus pas de SELECT mais des SET
--fait parti d'une procédure systématique dans nos développement.
--fait partie d'une manipulation de chaine pour créer du SQL dynamique
--est pratiquement la dernière instruction de la procedure
--devait construire le message de bonne finalisation de l'exécution

---

Par quelle méthode l'avez vous obtenue ?, Qu'y a t-il avant et après ?

Citation:

---

- sur l'ensemble du code, aucun ordre appelle une ressource externe à l'instance
- grosso modo c'est la 3ieme apparition de ce phénomène en 1 an. Ce qui est peu pour un job permanent.
--lors des incidents précédents le blocage avait perduré plusieurs jours et fini par bloquer d'autres demandes.
- On a créé une alerte sur le niveau de sévérité 16 qui envoi un mail. Pas de mail sur la période.

---

Cela ne vous renverras jamais rien. En effet, les erreurs ne sont trappées par le système d'alerte de l'Agent que si l’alerte est journalisée, c'est à dire à partir du niveau 19 ou bien si vous avez généré des RAISERROR WITH LOG.

Citation:

---

Il est possible/probable qu'on ne capture pas les bonnes informations.
Je cherche d'ailleurs à savoir comment récupérer les valeurs des variables de sessions d'une session précise.

---

Vous devriez mettre en place le "blocked process report".

A +

Nombre de bases :
Nous avions une structure de bases réparties qui aujourd'hui est rassemblées dans la même instance.
Ce qui représente moins de 40 bases.

Capture du code :
Nous avons utilisé la fonction sys.dm_exec_sql_text() et bdcc inputbuffer
Ce qu'il y a avant : commit;
Ce qu'il y a après : end;

Alerte :
Bien vu. C'était un fol espoir.
**Edit** : on a modifié l'alerte 208 pour qu'elle passe dorénavant par le Log
EXEC sp_altermessage @message_id = 208 ,@parameter = 'WITH_LOG' ,@parameter_value = 'true'

Mise en place de "blocked process report" :
Je ne sais pas de quoi il en retourne. Je vais m'informer. Merci.
**edit ** : De ce que j'ai pu comprendre le rapport est généré en cas de blocage. Ici ce n'est pas le cas. L'état est suspendu et n'est ni bloqué ni bloquant.

Citation:

---

Envoyé par Tagginfo

**edit ** : De ce que j'ai pu comprendre le rapport est généré en cas de blocage. Ici ce n'est pas le cas. L'état est suspendu et n'est ni bloqué ni bloquant.

---

Quand même commencer par le blocked process report. Car ce peut être un autre processus qui est bloqué qui entrainerait cette suspension.

Ensuite capturer les données des sessions, connections et request toutes les minutes si l'une des sessions est dans l'état suspended dans la vue sys.dm_exec_requests (et pas uniquement cette ligne...)

Puis analyser....

Cependant, je voit que le type d'atteinte est du ASYNC_NETWORK_IO. Ceci se produit du fait que la communication entre le serveur SQL et le client est lente. Par exemple un PC vérolé. Tentez didentifier la machine demanderesse de la requête et isolez là afin qu'elle n'accède plus à la base. Vérifiez là ensuite....

A +

Effectivement ASYNC_NETWORK_IO me semble être le nœud du problème car nous n'arrivons pas à justifier sa présence :
- Le code provient d'un job local donc en connexion via échange de mémoire.
- Le code n'appelle pas d'objet distants.

Ca reste un mystère ...

On continue nos collectes mais le fait est qu'on aura les mêmes éléments a se mettre sous la dent :(

Vérifie si c'est pas toujours le même client/application/adresse max/host qui fout le bordel.....

A +