Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2019-09-16
22:08:41 sean-k-mooney the rest of the test pass fine
22:08:59 sean-k-mooney i assume they just use sqlite
22:10:33 sean-k-mooney thats interesting its not in pip freeze in the tox env
22:11:08 sean-k-mooney oh there is not explcit py36 target
22:11:31 sean-k-mooney and it wont look for requirement-py3.txt by defualt
22:12:13 sean-k-mooney i might update the tox file in a sperate patch.
22:14:47 efried mriedem: https://storage.bhs1.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/logs_51/678051/4/check/nova-tox-collect-py37/f9b92d6/testr_results.html.gz looks like the root cause is some kind of timeout. If we could figure out where, we could probably extend it a bit and make the problem go away...?
22:15:56 efried mmph, it's a socket read, probably a real deadlock.
22:17:29 mriedem sean-k-mooney: do you have this? https://review.opendev.org/#/c/659388/
22:17:36 efried actually, it's the test timeout
22:17:52 mriedem efried: right,
22:17:55 mriedem that's a red herring
22:18:03 sean-k-mooney mriedem: apparently not but i cloned this on friday
22:18:13 mriedem i think we hit some db failure, switch eventlet context, and then never fail the test outright but it times out
22:18:32 mriedem sean-k-mooney: that migrate patch merged awhile back
22:18:45 sean-k-mooney mriedem: oh i cloned it form github so look like github sync for this is broken
22:18:47 mriedem sean-k-mooney: did you clone from github or opendev?
22:18:47 efried the time stamps are pretty funky on the log messages leading up to the exception.
22:18:54 mriedem efried: yup
22:19:01 mriedem sean-k-mooney: yeah you need opendev
22:19:02 efried nearly 12 minutes elapse
22:19:13 sean-k-mooney ya ok ill rebase
22:19:31 sean-k-mooney am should i still clean up the tox file seperatly
22:19:40 mriedem efried: b/c https://github.com/openstack/nova/blob/master/nova/tests/unit/db/test_migrations.py#L72
22:19:47 sean-k-mooney we done actully still support py 26 or py 33/34 right
22:19:55 sean-k-mooney *don't
22:20:17 mriedem sean-k-mooney: how about you clone from the current repo before asking questoins
22:20:18 efried 4 * 160 = 11m40s, yup, that's right on.
22:20:52 mriedem the timeouts on those were bumped a couple of years ago for a valid reason at the time (slow nodes i think)
22:20:58 mriedem https://github.com/openstack/nova/commit/71d6333f855e139894f497fc120487895a1d66ce
22:21:14 mriedem but the thread switch thing kills us
22:23:20 efried this is always on limestone-regionone??
22:25:09 efried that... seems like a thing
22:25:17 efried is it because limestone has slower nodes consistently?
22:25:26 efried or because of some particular config over there?
22:25:52 sean-k-mooney are the limesotone jobs gernerally slower or is it just this one thing that is failing
22:25:55 efried could we... increase the timeout s'more and see if it goes away? Not the greatest answer, but overall gate time wasted would be less
22:26:08 sean-k-mooney of the over all job is slow then it coudl be that its just slower in general
22:26:09 efried sean-k-mooney: I dunno, before digging into that I was going to see if anyone knew off the top.
22:26:37 efried not sure how I would look into that, other than clicking through a zillion different builds
22:26:40 mriedem yes it's always limestone
22:26:46 mriedem idk if they are slower or what, you'd have to ask in infra
22:27:14 mriedem there is probably some way to find average job time per node provider and nova openstack-tox-py36 job or something
22:27:16 sean-k-mooney infra have many grapha dashborads that track things but i dont know if they yave abuild time per regoin one
22:27:25 sean-k-mooney you could proably figure it out form logstash
22:27:42 mriedem i think awhile back i had wondered if those nodes used some different mysql binary or something
22:28:16 mriedem for everything to be not crazy though it should be the same ubuntu 18.04 image and such regardless of node provider
22:28:23 sean-k-mooney they should all use the nodepool image and then hit the infra mirros which are avaible via afs in all regions right
22:28:26 sean-k-mooney so it shoudl be the same
22:29:17 efried http://zuul.openstack.org/builds?job_name=openstack-tox-py27&branch=master&project=openstack%2Fnova but this table doesn't show the node provider...
22:29:21 sean-k-mooney i think infra has been uploading its own image nightly since the zuul v2 days to not have random things break in diffrent clouds
22:30:16 logan- o/ from limestone
22:30:50 efried this slow bastard happened on rax https://zuul.opendev.org/t/openstack/build/38181c3314284545943b38b52c72f8d7/log/job-output.txt
22:31:54 sean-k-mooney logan- they are trying to debug a test that seam to be hitting a timeout
22:32:16 sean-k-mooney logan-: but only (mostly?) happens in limestone-regionone
22:33:03 alex_xu efried: I'm here
22:33:04 sean-k-mooney logan-: so we were wondering if limesotne is generally slower the other providre and hiting the timeout more often or if it could be a config/could issue
22:33:38 sean-k-mooney logan-: e.g. is there something differnet that could make it fail more often on limestone or it that just a red herring
22:33:45 efried alex_xu: Can you, or Rui, or luyao, or someone please formulate a bullet for vpmem for the train cycle highlights in a followon to https://review.opendev.org/#/c/681943/ ?
22:34:11 alex_xu efried: got it, will do today
22:34:25 efried alex_xu: If you seed the message, I'll scrub the grammar etc. Thanks.
22:34:38 alex_xu efried: thanks
22:35:38 logan- i'm not sure if our testcloud is slower than other nodepool providers. certainly the image would be the same as any other nodepool node. looking thru the log.. i'm curious if the job hangs somewhere specific, or if its just slower in general. and if our nodes are just showing up slower on average i'd like to know so we can figure out if it is h/w or config related.
22:36:23 efried logan-: The thing we're trying to nail down is http://logstash.openstack.org/#/dashboard/file/logstash.json?query=message:%5C%22sqlalchemy.exc.InterfaceError:%20(pymysql.err.InterfaceError)%20(0,%20'')%5C%22%20AND%20tags:%5C%22console%5C%22%20AND%20voting:1&from=864000s
22:36:48 efried we consistently see the test suite time out on the same 1-3 tests
22:39:22 efried logan-: and if you punch the `node_provider` checkbox on the left-hand side next to the result list, you see it's *always* limestone-regionone
22:40:52 logan- https://storage.bhs1.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/logs_51/678051/4/check/nova-tox-collect-py37/f9b92d6/mysql/error.log are any of these messages at the bottom pertinent?
22:42:08 openstackgerrit Matt Riedemann proposed openstack/nova master: Create volume attachment during boot from volume in compute https://review.opendev.org/541420
22:42:58 mriedem logan-: we're not sure, we need zzzeek's help for that
22:43:58 mriedem those are definitely related to the opportunistic db tests that fail,
22:44:07 mriedem the db is a random db name created by the test fixture,
22:44:12 mriedem openstack_citest is setup by a script on the node
22:44:32 mriedem https://github.com/openstack/nova/blob/master/tools/test-setup.sh does the mysql/postgresql setup
22:45:05 efried logan-: this might be what you were already looking at, but I did a compare of the mysql error log on a "good" run and a "bad" one, and didn't see significant differences.
22:45:21 efried logan-: see bottom-most comment on https://review.opendev.org/#/c/678051/
22:45:57 logan- yep, that's what i was wondering, thanks
22:47:05 efried although the bad one is taking way longer...
22:47:12 efried but dunno if that's cause or effect
22:47:39 logan- to answer the general question -- I don't know of anything significantly different on our nodes. they're pretty standard dual proc intel systems with ssds. I wonder if there's something in particular with this test that is wrecking the node somehow.
22:48:49 efried mhm, mriedem here's an interesting data point: in the "good" one, all those "abort" messages come through in under a minute. In the "bad" one, the first 16 or so are under a minute, then we start getting long delays.
22:49:32 efried now, IIUC, everything before those "abort" messages is just setup, and the "abort" things are happening during the actual meat of the test. So I guess that's not really surprising.
22:50:21 openstackgerrit Matt Riedemann proposed openstack/nova master: Create volume attachment during boot from volume in compute https://review.opendev.org/541420
22:53:37 efried It would be painful, but maybe if we knew what operations were being run, it would give us a clue as to what's happening when it starts to grind down.
22:54:08 efried anybody know how to turn on like trace logs to see the sql statements themselves as they're issued?
22:54:17 openstackgerrit Matt Riedemann proposed openstack/nova master: DNM: Stop using volume_api.initialize_connection https://review.opendev.org/682508
22:55:20 mriedem efried: i want to say https://docs.openstack.org/nova/latest/configuration/config.html#database.connection_debug or
22:55:25 mriedem https://docs.openstack.org/nova/latest/configuration/config.html#database.connection_trace
22:57:54 alex_xu efried: https://review.opendev.org/682509
22:58:19 efried alex_xu: cool, thank you.
22:58:26 alex_xu efried: np!
22:58:36 efried alex_xu: since this is market-y, we probably don't want to mention the generic resource framework
22:58:49 alex_xu efried: ah, got it
22:58:59 efried that's a thing only devs would care about, at least until it reaps perf benefits via placement, which is a ways off.
22:59:14 efried alex_xu: perhaps kill that sentence and instead explain a bit more what vpmem is
22:59:15 alex_xu efried: sev mentioned that, that is why I follow
22:59:24 efried oh? looking...
23:00:05 efried alex_xu: yeah, I'm looking for something corresponding to "to protect users against attackers or rogue administrators snooping on
23:00:05 efried their workloads when using the libvirt compute driver"
23:00:16 alex_xu efried: got it
23:00:31 alex_xu mriedem: you are super fast

Earlier   Later