Timeouts in System.Text.Json.Tests on arm32

[AaronRobinsonMSFT]

#67858

Console log: 'System.Text.Json.Tests' from job 0e2f0129-97a5-4449-a6f1-4f6d48f286d1 (ubuntu.1804.armarch.open) using docker image mcr.microsoft.com/dotnet-buildtools/prereqs:ubuntu-18.04-helix-arm32v7-bfcd90a-20200121150440 on ddvsotx2l053
running $HELIX_CORRELATION_PAYLOAD/scripts/437cee12e49841d097023962d57d444e/execute.sh in /ssd/work/A22408F2/w/A0840945/e max 2700 seconds

=================

Console log: 'System.Text.Json.Tests' from job cc08232a-0565-4446-a309-8e67f6b5ff0a (ubuntu.1804.armarch.open) using docker image mcr.microsoft.com/dotnet-buildtools/prereqs:alpine-3.14-helix-arm32v7-20210910135806-8a6f4f3 on ddvsotx2l143
running $HELIX_CORRELATION_PAYLOAD/scripts/00f3104607ef4bc4ab7713de646b08be/execute.sh in /ssd/work/A07A0914/w/B302093F/e max 2700 seconds

#67852

[ghost]

Tagging subscribers to this area: @dotnet/area-system-text-json, @gregsdennis
See info in area-owners.md if you want to be subscribed.

Issue Details

---

#67858

Console log: 'System.Text.Json.Tests' from job 0e2f0129-97a5-4449-a6f1-4f6d48f286d1 (ubuntu.1804.armarch.open) using docker image mcr.microsoft.com/dotnet-buildtools/prereqs:ubuntu-18.04-helix-arm32v7-bfcd90a-20200121150440 on ddvsotx2l053
running $HELIX_CORRELATION_PAYLOAD/scripts/437cee12e49841d097023962d57d444e/execute.sh in /ssd/work/A22408F2/w/A0840945/e max 2700 seconds

=================

Console log: 'System.Text.Json.Tests' from job cc08232a-0565-4446-a309-8e67f6b5ff0a (ubuntu.1804.armarch.open) using docker image mcr.microsoft.com/dotnet-buildtools/prereqs:alpine-3.14-helix-arm32v7-20210910135806-8a6f4f3 on ddvsotx2l143
running $HELIX_CORRELATION_PAYLOAD/scripts/00f3104607ef4bc4ab7713de646b08be/execute.sh in /ssd/work/A07A0914/w/B302093F/e max 2700 seconds

#67852

Author:	AaronRobinsonMSFT
Assignees:	-
Labels:	arch-arm32, area-System.Text.Json, os-linux
Milestone:	-

[jkoritzinsky]

Happening here as well: #67676 (comment)

[elinor-fung]

Hit again in #67635.

A bunch of different tests being detected as long running - from one of the logs:

[Long Running Test] 'System.Text.Json.Serialization.Tests.ConstructorTests_AsyncStream.MultipleThreads', Elapsed: 00:30:23
[Long Running Test] 'System.Text.Json.Serialization.Tests.ReferenceHandlerTestsDynamic_AsyncStream.TestJsonPathDoesNotFailOnMultiThreads', Elapsed: 00:30:42
[Long Running Test] 'System.Text.Json.Serialization.Tests.ReferenceHandlerTestsDynamic_AsyncStreamWithSmallBuffer.TestJsonPathDoesNotFailOnMultiThreads', Elapsed: 00:29:31
[Long Running Test] 'System.Text.Json.Serialization.Tests.StreamTests_Sync.VeryLargeJsonFileTest', Elapsed: 00:24:47
[Long Running Test] 'System.Text.Json.Serialization.Tests.CacheTests.MultipleTypes', Elapsed: 00:28:42
[Long Running Test] 'System.Text.Json.Serialization.Tests.ConstructorTests_SyncStream.MultipleThreads', Elapsed: 00:30:17
[Long Running Test] 'System.Text.Json.Serialization.Tests.ConstructorTests_Span.MultipleThreads', Elapsed: 00:29:08
[Long Running Test] 'System.Text.Json.Serialization.Tests.CollectionTestsDynamic_AsyncStream.WriteNestedAsyncEnumerable', Elapsed: 00:25:21
[Long Running Test] 'System.Text.Json.Serialization.Tests.CollectionTestsDynamic_AsyncStreamWithSmallBuffer.WriteSequentialNestedAsyncEnumerables', Elapsed: 00:28:11
[Long Running Test] 'System.Text.Json.Serialization.Tests.ConstructorTests_String.MultipleThreads', Elapsed: 00:26:51
[Long Running Test] 'System.Text.Json.Serialization.Tests.StreamTests_Async.VeryLargeJsonFileTest', Elapsed: 00:09:22
[Long Running Test] 'System.Text.Json.Tests.JsonDocumentTests.ParseJson_UnseekableStream', Elapsed: 00:26:40
[Long Running Test] 'System.Text.Json.Serialization.Tests.ReferenceHandlerTestsDynamic_String.TestJsonPathDoesNotFailOnMultiThreads', Elapsed: 00:26:39
[Long Running Test] 'System.Text.Json.Serialization.Tests.StreamTests_DeserializeAsyncEnumerable.DeserializeAsyncEnumerable_ReadSimpleObjectAsync', Elapsed: 00:25:34
[Long Running Test] 'System.Text.Json.Serialization.Tests.StreamTests_AsyncWithSmallBuffer.VeryLargeJsonFileTest', Elapsed: 00:06:04

[elinor-fung]

There over 50 hits in the past day - marking as blocking-clean-ci. Nothing in the week before that though - some recent change?

WorkItems
| where FriendlyName == "System.Text.Json.Tests"
| where  Queued > ago(1d)
| where Status == "Timeout"
| where QueueName contains "arm"
| join Jobs on JobId
| project
  Queued,
  FriendlyName, ExitCode, Status,
  ConsoleUri,
  PhaseName = tostring(parse_json(Properties)["System.PhaseName"]),
  Pipeline = tostring(parse_json(Properties).DefinitionName),
  RuntimeFlavor = tostring(parse_json(Properties).runtimeFlavor),
  BuildId = tostring(parse_json(Properties).BuildId),
  QueueName, Source

[danmoseley]

cc @ViktorHofer as test monitor -- is this always 32 bit ARM? If so can we disable just for that?

[eiriktsarpalis]

@krwq would it make sense to move some of the tests listed in #67878 (comment) to OuterLoop?

[danmoseley]

I'll disable affected tests for Arm32.

[ViktorHofer]

I didn't notice these timeouts as I only looked at test failures yesterday... Thanks Dan for disabling them.

[danmoseley]

This was likely regressed by @krwq in #67838. That slowed things down, which would explain why it's only on Arm; it's also debug only, which is what we see; and it began happening fairly consistently at the moment that PR went in.

I think it's easier for me to disable those asserts on Arm.

BTW I wrote a script to read the console output for all the failures, and these are the tests that fail -- perhaps the slowest tests that run through the asserts?

System.Text.Json.Serialization.Tests.CacheTests.MultipleTypes
System.Text.Json.Serialization.Tests.CollectionTestsDynamic_AsyncStream.WriteNestedAsyncEnumerable
System.Text.Json.Serialization.Tests.CollectionTestsDynamic_AsyncStreamWithSmallBuffer.WriteSequentialNestedAsyncEnumerables
System.Text.Json.Serialization.Tests.ConstructorTests_AsyncStream.MultipleThreads
System.Text.Json.Serialization.Tests.ConstructorTests_Span.MultipleThreads
System.Text.Json.Serialization.Tests.ConstructorTests_String.MultipleThreads
System.Text.Json.Serialization.Tests.ConstructorTests_SyncStream.MultipleThreads
System.Text.Json.Serialization.Tests.ContinuationTests.InvalidJsonShouldFailAtAnyPosition_Stream
System.Text.Json.Serialization.Tests.ContinuationTests.ShouldWorkAtAnyPosition_Stream
System.Text.Json.Serialization.Tests.NumberHandlingTests.Number_AsCollectionElement_RoundTrip
System.Text.Json.Serialization.Tests.NumberHandlingTests.Number_AsRootType_RoundTrip
System.Text.Json.Serialization.Tests.ReferenceHandlerTestsDynamic_AsyncStream.TestJsonPathDoesNotFailOnMultiThreads
System.Text.Json.Serialization.Tests.ReferenceHandlerTestsDynamic_AsyncStreamWithSmallBuffer.TestJsonPathDoesNotFailOnMultiThreads
System.Text.Json.Serialization.Tests.ReferenceHandlerTestsDynamic_String.TestJsonPathDoesNotFailOnMultiThreads
System.Text.Json.Serialization.Tests.StreamTests_Async.DeepNestedJsonFileTest
System.Text.Json.Serialization.Tests.StreamTests_Async.HandleCollectionsAsync
System.Text.Json.Serialization.Tests.StreamTests_Async.LargeJsonFile
System.Text.Json.Serialization.Tests.StreamTests_Async.NestedJsonFileCircularDependencyTest
System.Text.Json.Serialization.Tests.StreamTests_Async.VeryLargeJsonFileTest
System.Text.Json.Serialization.Tests.StreamTests_AsyncWithSmallBuffer.DeepNestedJsonFileTest
System.Text.Json.Serialization.Tests.StreamTests_AsyncWithSmallBuffer.HandleCollectionsAsync
System.Text.Json.Serialization.Tests.StreamTests_AsyncWithSmallBuffer.NestedJsonFileCircularDependencyTest
System.Text.Json.Serialization.Tests.StreamTests_AsyncWithSmallBuffer.VeryLargeJsonFileTest
System.Text.Json.Serialization.Tests.StreamTests_DeserializeAsyncEnumerable.DeserializeAsyncEnumerable_ReadSimpleObjectAsync
System.Text.Json.Serialization.Tests.StreamTests_Sync.DeepNestedJsonFileTest
System.Text.Json.Serialization.Tests.StreamTests_Sync.HandleCollectionsAsync
System.Text.Json.Serialization.Tests.StreamTests_Sync.LargeJsonFile
System.Text.Json.Serialization.Tests.StreamTests_Sync.NestedJsonFileCircularDependencyTest
System.Text.Json.Serialization.Tests.StreamTests_Sync.VeryLargeJsonFileTest
System.Text.Json.Tests.JsonDocumentTests.ParseJson_UnseekableStream
System.Text.Json.Tests.Utf8JsonReaderTests.InvalidJsonStringVariousSegmentSizes
System.Text.Json.Tests.Utf8JsonReaderTests.ReadJsonStringsWithCommentsAndTrailingCommas
System.Text.Json.Tests.Utf8JsonReaderTests.TestPartialJsonReader
System.Text.Json.Tests.Utf8JsonWriterTests.WriteNumbers

[danmoseley]

If someone can sign off on #68027, I'm inclined to merge it immediately since this is failing once every hour.

[krwq]

Signed off, sorry for the slowdown