[CDRIVER-1216] SDAM performance assumption incorrect on zSeries Created: 29/Apr/16  Updated: 10/Aug/16  Resolved: 04/Aug/16

Status: Closed
Project: C Driver
Component/s: libmongoc
Affects Version/s: None
Fix Version/s: 1.4.0

Type: Bug Priority: Major - P3
Reporter: Hannes Magnusson Assignee: A. Jesse Jiryu Davis
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related

 Description   

The test_seed_list() (connection_option_t=CONNECT|RECONNECT) tests all fail on zSeries.

 
   if (connection_option == CONNECT || connection_option == RECONNECT) {
      start = bson_get_monotonic_time ();
 
      /* only localhost:port responds to initial discovery. the other seeds are
       * discarded from replica set topology, but remain for sharded. */
      ASSERT_OR_PRINT (mongoc_client_command_simple (
         client, "test", tmp_bson("{'foo': 1}"),
         primary_pref, &reply, &error), error);
 
      /* discovery should be quick despite down servers, say < 100ms */
      duration_usec = bson_get_monotonic_time () - start;
      ASSERT_CMPTIME ((int) (duration_usec / 1000), 100);
/* .... */
}

This almost always fail with the values ranging between 100 and 350.
In rare cases they pass.

2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       stream: TRACE: mongoc_stream_writev():161 writev = 0x83fbc310 [9]
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       stream: 00000:  3a 00 00 00 04 00 00 00  00 00 00 00 d4 07 00 00  : . . . . . . .  . . . . . . . .
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       stream: 00010:  04 00 00 00 61 64 6d 69  6e 2e 24 63 6d 64 00 00  . . . . a d m i  n . $ c m d . .
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       stream: 00020:  00 00 00 ff ff ff ff 13  00 00 00 10 69 73 4d 61  . . . . . . . .  . . . . i s M a
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       stream: 00030:  73 74 65 72 00 01 00 00  00 00                    s t e r . . . .  . .
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       stream: ENTRY: _mongoc_stream_socket_writev():202
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: ENTRY: mongoc_socket_sendv():1089
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: ENTRY: _mongoc_socket_try_sendv():998
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: TRACE: _mongoc_socket_try_sendv():1004 sendbuf = 0x83fbd290 [9]
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: 00000:  3a 00 00 00 04 00 00 00  00 00 00 00 d4 07 00 00  : . . . . . . .  . . . . . . . .
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: 00010:  04 00 00 00 61 64 6d 69  6e 2e 24 63 6d 64 00 00  . . . . a d m i  n . $ c m d . .
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: 00020:  00 00 00 ff ff ff ff 13  00 00 00 10 69 73 4d 61  . . . . . . . .  . . . . i s M a
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: 00030:  73 74 65 72 00 01 00 00  00 00                    s t e r . . . .  . .
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: TRACE: _mongoc_socket_try_sendv():1020 Send 58 out of 4 bytes
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket:  EXIT: _mongoc_socket_try_sendv():1050
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: TRACE: mongoc_socket_sendv():1100 Sent 58 (of 4) out of iovcnt=9
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 58 -= 4
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 54 -= 4
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 50 -= 4
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 46 -= 4
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 42 -= 4
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 38 -= 11
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 27 -= 4
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 23 -= 4
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: TRACE: mongoc_socket_sendv():1125 still got bytes left: sent -= iov_len: 19 -= 19
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: TRACE: mongoc_socket_sendv():1134 Finished the iovecs
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket:  EXIT: mongoc_socket_sendv():1165
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: TRACE: mongoc_socket_errno():307 Current errno: 115
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       stream:  EXIT: _mongoc_stream_socket_writev():208
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       stream:  EXIT: mongoc_stream_writev():164
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       stream: ENTRY: _mongoc_stream_socket_poll():226
2016/04/29 17:48:39.0986: [ 7458]:    TRACE:       socket: ENTRY: mongoc_socket_poll():217
2016/04/29 17:48:39.0986: [ 7472]:    TRACE:       socket: ENTRY: _mongoc_socket_wait():113
2016/04/29 17:48:39.0986: [ 7472]:    TRACE:       socket:  EXIT: _mongoc_socket_wait():154
2016/04/29 17:48:39.0986: [ 7472]:    TRACE:       socket:  GOTO: mongoc_socket_accept_ex():442 again
2016/04/29 17:48:39.0986: [ 7472]:    TRACE:       socket: TRACE: _mongoc_socket_capture_errno():336 setting errno: 0
2016/04/29 17:48:39.0986: [ 7472]:    TRACE:       socket: ENTRY: _mongoc_socket_setnodelay():271
2016/04/29 17:48:39.0986: [ 7472]:    TRACE:       socket:  EXIT: _mongoc_socket_setnodelay():283
2016/04/29 17:48:39.0986: [ 7472]:    TRACE:       socket:  EXIT: mongoc_socket_accept_ex():467
2016/04/29 17:48:39.0986: [ 7472]:    TRACE:       socket: ENTRY: mongoc_socket_accept_ex():424
2016/04/29 17:48:39.0986: [ 7472]:    TRACE:       socket: TRACE: _mongoc_socket_capture_errno():336 setting errno: 11
2016/04/29 17:48:39.0986: [ 7472]:    TRACE:       socket: TRACE: _mongoc_socket_errno_is_again():360 errno is: 11
2016/04/29 17:48:39.0986: [ 7472]:    TRACE:       socket: ENTRY: _mongoc_socket_wait():113
2016/04/29 17:48:39.0986: [ 7472]:    TRACE:       socket:  EXIT: _mongoc_socket_wait():174
2016/04/29 17:48:39.0986: [ 7472]:    TRACE:       socket:  EXIT: mongoc_socket_accept_ex():444
2016/04/29 17:48:39.0986: [ 7472]:    TRACE:       socket: ENTRY: mongoc_socket_accept_ex():424
2016/04/29 17:48:39.0986: [ 7473]:    TRACE:       socket: TRACE: _mongoc_socket_errno_is_again():360 errno is: 11
2016/04/29 17:48:39.0986: [ 7472]:    TRACE:       socket: TRACE: _mongoc_socket_capture_errno():336 setting errno: 11
2016/04/29 17:48:39.0986: [ 7475]:    TRACE:       socket: TRACE: _mongoc_socket_errno_is_again():360 errno is: 11
2016/04/29 17:48:39.0986: [ 7475]:    TRACE:       socket: ENTRY: _mongoc_socket_wait():113
2016/04/29 17:48:39.0986: [ 7475]:    TRACE:       socket:  EXIT: _mongoc_socket_wait():154
2016/04/29 17:48:39.0986: [ 7475]:    TRACE:       socket:  GOTO: mongoc_socket_accept_ex():442 again
2016/04/29 17:48:39.0986: [ 7475]:    TRACE:       socket: TRACE: _mongoc_socket_capture_errno():336 setting errno: 0
2016/04/29 17:48:39.0986: [ 7475]:    TRACE:       socket: ENTRY: _mongoc_socket_setnodelay():271
2016/04/29 17:48:39.0986: [ 7475]:    TRACE:       socket:  EXIT: _mongoc_socket_setnodelay():283
2016/04/29 17:48:39.0986: [ 7475]:    TRACE:       socket:  EXIT: mongoc_socket_accept_ex():467
2016/04/29 17:48:39.0986: [ 7475]:    TRACE:       socket: ENTRY: mongoc_socket_accept_ex():424
2016/04/29 17:48:39.0986: [ 7475]:    TRACE:       socket: TRACE: _mongoc_socket_capture_errno():336 setting errno: 11
2016/04/29 17:48:39.0986: [ 7475]:    TRACE:       socket: TRACE: _mongoc_socket_errno_is_again():360 errno is: 11
2016/04/29 17:48:39.0986: [ 7475]:    TRACE:       socket: ENTRY: _mongoc_socket_wait():113
2016/04/29 17:48:39.0986: [ 7475]:    TRACE:       socket:  EXIT: _mongoc_socket_wait():174

....

2016/04/29 17:48:40.0101: [ 7472]:    TRACE:       socket:  EXIT: mongoc_socket_accept_ex():444
2016/04/29 17:48:40.0101: [ 7472]:    TRACE:       socket: ENTRY: mongoc_socket_accept_ex():424
2016/04/29 17:48:40.0101: [ 7472]:    TRACE:       socket: TRACE: _mongoc_socket_capture_errno():336 setting errno: 11
2016/04/29 17:48:40.0101: [ 7472]:    TRACE:       socket: TRACE: _mongoc_socket_errno_is_again():360 errno is: 11
2016/04/29 17:48:40.0101: [ 7472]:    TRACE:       socket: ENTRY: _mongoc_socket_wait():113
2016/04/29 17:48:40.0101: [ 7472]:    TRACE:       socket:  EXIT: _mongoc_socket_wait():174
2016/04/29 17:48:40.0101: [ 7472]:    TRACE:       socket:  EXIT: mongoc_socket_accept_ex():444
2016/04/29 17:48:40.0101: [ 7472]:    TRACE:       socket: ENTRY: mongoc_socket_accept_ex():424
2016/04/29 17:48:40.0101: [ 7472]:    TRACE:       socket: TRACE: _mongoc_socket_capture_errno():336 setting errno: 11
2016/04/29 17:48:40.0101: [ 7472]:    TRACE:       socket: TRACE: _mongoc_socket_errno_is_again():360 errno is: 11

....

2016/04/29 17:48:40.0145: [ 7475]:    TRACE:       socket:  EXIT: mongoc_socket_accept_ex():444
2016/04/29 17:48:40.0145: [ 7475]:    TRACE:       socket: ENTRY: mongoc_socket_accept_ex():424
2016/04/29 17:48:40.0145: [ 7476]:    TRACE:       stream: ENTRY: mongoc_stream_readv():226
2016/04/29 17:48:40.0145: [ 7475]:    TRACE:       socket: TRACE: _mongoc_socket_capture_errno():336 setting errno: 11
2016/04/29 17:48:40.0145: [ 7476]:    TRACE:       stream: ENTRY: _mongoc_stream_socket_readv():139
2016/04/29 17:48:40.0145: [ 7476]:    TRACE:       socket: ENTRY: mongoc_socket_recv():797
2016/04/29 17:48:40.0145: [ 7479]:    TRACE:       buffer: ENTRY: _mongoc_buffer_fill():211
2016/04/29 17:48:40.0145: [ 7477]:    TRACE:       stream: 002b0:  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
2016/04/29 17:48:40.0145: [ 7475]:    TRACE:       socket: TRACE: _mongoc_socket_errno_is_again():360 errno is: 11
2016/04/29 17:48:40.0145: [ 7475]:    TRACE:       socket: ENTRY: _mongoc_socket_wait():113
2016/04/29 17:48:40.0145: [ 7474]:    TRACE:       socket:  EXIT: mongoc_socket_accept_ex():444
2016/04/29 17:48:40.0145: [ 7474]:    TRACE:       socket: ENTRY: mongoc_socket_accept_ex():424
2016/04/29 17:48:40.0145: [ 7479]:    TRACE:       stream: ENTRY: mongoc_stream_read():268
2016/04/29 17:48:40.0145: [ 7474]:    TRACE:       socket: TRACE: _mongoc_socket_capture_errno():336 setting errno: 11
2016/04/29 17:48:40.0145: [ 7474]:    TRACE:       socket: TRACE: _mongoc_socket_errno_is_again():360 errno is: 11
2016/04/29 17:48:40.0145: [ 7474]:    TRACE:       socket: ENTRY: _mongoc_socket_wait():113
2016/04/29 17:48:40.0145: [ 7474]:    TRACE:       socket:  EXIT: _mongoc_socket_wait():174
2016/04/29 17:48:40.0145: [ 7478]:    TRACE:       stream:  EXIT: _mongoc_stream_socket_readv():178
2016/04/29 17:48:40.0145: [ 7477]:    TRACE:       stream: 002c0:  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
2016/04/29 17:48:40.0145: [ 7478]:    TRACE:       stream: TRACE: mongoc_stream_readv():236 readv = 0x3ff6f7feb58 [1]
2016/04/29 17:48:40.0145: [ 7477]:    TRACE:       stream: 002d0:  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
2016/04/29 17:48:40.0145: [ 7478]:    TRACE:       stream: 00000:  3a 00 00 00 02 00 00 00  00 00 00 00 d4 07 00 00  : . . . . . . .  . . . . . . . .
2016/04/29 17:48:40.0145: [ 7477]:    TRACE:       stream: 002e0:  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
2016/04/29 17:48:40.0145: [ 7477]:    TRACE:       stream: 002f0:  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
2016/04/29 17:48:40.0145: [ 7478]:    TRACE:       stream: 00010:  04 00 00 00 61 64 6d 69  6e 2e 24 63 6d 64 00 00  . . . . a d m i  n . $ c m d . .
2016/04/29 17:48:40.0145: [ 7477]:    TRACE:       stream: 00300:  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
2016/04/29 17:48:40.0145: [ 7478]:    TRACE:       stream: 00020:  00 00 00 ff ff ff ff 13  00 00 00 10 69 73 4d 61  . . . . . . . .  . . . . i s M a
2016/04/29 17:48:40.0145: [ 7477]:    TRACE:       stream: 00310:  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
2016/04/29 17:48:40.0145: [ 7478]:    TRACE:       stream: 00030:  73 74 65 72 00 01 00 00  00 00 00 00 00 00 00 00  s t e r . . . .  . . . . . . . .
2016/04/29 17:48:40.0145: [ 7477]:    TRACE:       stream: 00320:  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
2016/04/29 17:48:40.0145: [ 7478]:    TRACE:       stream: 00040:  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
2016/04/29 17:48:40.0145: [ 7477]:    TRACE:       stream: 00330:  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
2016/04/29 17:48:40.0145: [ 7478]:    TRACE:       stream: 00050:  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
2016/04/29 17:48:40.0145: [ 7477]:    TRACE:       stream: 00340:  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
2016/04/29 17:48:40.0145: [ 7473]:    TRACE:       socket:  EXIT: _mongoc_socket_wait():174



 Comments   
Comment by Githook User [ 03/Aug/16 ]

Author:

{u'username': u'ajdavis', u'name': u'A. Jesse Jiryu Davis', u'email': u'jesse@mongodb.com'}

Message: CDRIVER-1216 live tests on zSeries
Branch: master
https://github.com/mongodb/mongo-c-driver/commit/b6744aa68c77755d5bb53294110ba244d21b39c2

Comment by Githook User [ 03/Aug/16 ]

Author:

{u'username': u'ajdavis', u'name': u'A. Jesse Jiryu Davis', u'email': u'jesse@mongodb.com'}

Message: CDRIVER-1216 test shouldn't rely on getaddrinfo timing
Branch: master
https://github.com/mongodb/mongo-c-driver/commit/f2578af5bf098890a9b8286c151be36b4482b7c3

Comment by Hannes Magnusson [ 29/Apr/16 ]

Example build: https://evergreen.mongodb.com/task_log_raw/mongo_c_driver_rhel_72_zseries_integration_test_latest_9a31e4c9adc8159ce64d43942b86999eab0eb940_16_04_27_23_11_23/0?type=T

Comment by Hannes Magnusson [ 29/Apr/16 ]

These are the only tests that fail on zSeries so far (still working on enable few more variations)

Generated at Wed Feb 07 21:11:55 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.