Starting preliminary 0.94 testing - "Headless fullnode" - page 9.

doug_armory

sr. member

Activity: 255

Merit: 250

Senior Developer - Armory

Quote from: Roy Badami on June 09, 2015, 05:37:15 PM

I should also point out that this is my first time building in a very long time (I think the last time was before you offered prebuilt Mac binaries) so in particular I have absolutely no evidence that there isn't something subtly borked in my build environment.

The OS X build process is mostly self-contained. Knock on wood and all but I've found that even the slightest hiccups cause Armory to not build properly. In other words, your environment's probably fine.

Roy Badami

hero member

Activity: 563

Merit: 500

Quote from: goatpig on June 09, 2015, 05:40:07 PM

If you want to manually set your thread counts regardless, go inside BlockWriteBatcher.cpp and do the following:

1) comment out line 2004 to prevent thread adjustment
2) hardcode values in the BlockWriteBatcher ctor (line 112 for fullnode, 99 for supernode)

Could well be just chance since the behaviour before was clearly somewhat nondeterministric. But I did the above and it synced my wallets perfectly first time (and I hadn't managed to get a successfully sync at all so far up till now). If I get the chance tomorrow I'll nuke the databases and try again to confirm whether this is repeatable.

Just to confirm, only change I made was as you suggested:

Code:

diff --git a/cppForSwig/BlockWriteBatcher.cpp b/cppForSwig/BlockWriteBatcher.cpp
index 153558b..c11348f 100644
--- a/cppForSwig/BlockWriteBatcher.cpp
+++ b/cppForSwig/BlockWriteBatcher.cpp
@@ -109,6 +109,8 @@ BlockWriteBatcher::BlockWriteBatcher(
       if (readers < 1)
          readers = 1;
 
+      workers = readers = 1;
+
       setThreadCounts(readers, workers, 1);
    }
 }
@@ -2001,7 +2003,7 @@ void BlockBatchProcessor::writeThread()
 
       commitedId_.fetch_add(1, memory_order_release);
       commitObject->writeTime_ = clock() - commitObject->writeTime_;
-      commitObject->processor_->adjustThreadCount(commitObject);
+//      commitObject->processor_->adjustThreadCount(commitObject);
 
       thread cleanup(cleanUpThread, commitObject);
       if (cleanup.joinable())

Roy Badami

hero member

Activity: 563

Merit: 500

Thanks. I'm sure you're right, but I might try nailing down the thread count anyway. (Probably not tonight though given how long it takes to rebuild on this slow machine. Is there no way of doing an incremental build on a Mac?)

roy

goatpig

legendary

Activity: 3640

Merit: 1345

Armory Developer

This isn't the thread adjustment, it's failing to grab the block data or the data has expired before it got to process it. It's consistent with the symptoms of the issue I'm going after ATM so I'll have you wait for the fix to try this again. Right now I don't think there is anything else you can do about it.

If you want to manually set your thread counts regardless, go inside BlockWriteBatcher.cpp and do the following:

1) comment out line 2004 to prevent thread adjustment
2) hardcode values in the BlockWriteBatcher ctor (line 112 for fullnode, 99 for supernode)

Roy Badami

hero member

Activity: 563

Merit: 500

I should also point out that this is my first time building in a very long time (I think the last time was before you offered prebuilt Mac binaries) so in particular I have absolutely no evidence that there isn't something subtly borked in my build environment.

Roy Badami

hero member

Activity: 563

Merit: 500

Ah, interesting. In armorycpp.log, it looks like it got to around block 130,000 and then readjusted the number of threads. ~~No more~~ Only one more "finished applying" message after the thread readjust message - which takes it up to block 130,250 (which is before I was using bitcoin - so consistent with the wallets all showing zero balance).

Code:

-WARN  - 1433882811: (BlockUtils.cpp:1071) Scanning from 0 to 360192
-WARN  - 1433882817: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 2500
-WARN  - 1433882819: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 85000
-WARN  - 1433882822: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 105000
-WARN  - 1433882824: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 115000
-WARN  - 1433882828: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 120000
-WARN  - 1433882830: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 125000
-WARN  - 1433882832: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 127500
-WARN  - 1433882838: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 130000
-INFO  - 1433882842: (BlockWriteBatcher.cpp:2067)  &&&&&&&&& cumulatedReadTime: 41.2889s
-INFO  - 1433882842: (BlockWriteBatcher.cpp:2068)  &&&&&&&&& cumulatedWorkTime: 9.8054s
-INFO  - 1433882842: (BlockWriteBatcher.cpp:2069)  &&&&&&&&& cumulatedWriteTime: 0.186015s
-WARN  - 1433882842: (BlockWriteBatcher.cpp:2083) Readjusting thread count: 
-WARN  - 1433882842: (BlockWriteBatcher.cpp:2084) 2 readers
-WARN  - 1433882842: (BlockWriteBatcher.cpp:2085) 1 workers
-WARN  - 1433882842: (BlockWriteBatcher.cpp:2086) 1 writers
-WARN  - 1433882842: (BlockWriteBatcher.cpp:2087) 1 old reader count
-WARN  - 1433882842: (BlockWriteBatcher.cpp:2088) 1 old worker count
-WARN  - 1433882842: (BlockWriteBatcher.cpp:2089) 1 old writer count
-WARN  - 1433882842: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 132500
-WARN  - 1433882844: (BlockWriteBatcher.cpp:503) --- cumulatedBatchSleep: 0
-WARN  - 1433882844: (BlockWriteBatcher.cpp:545) --- feedSleep: 0 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:548) --- workers: 0 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:551) --- writeStxo: 0.004949 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:553) --- writeStxo_grabMutex: 6.9e-05 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:556) --- waitingOnSerThread: 0.123388 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:558) --- waitForDataToWrite: 46.0291 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:562) --- checkForCollisions: 0.00029 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:564) --- getExistingKeys: 0.000519 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:566) --- getNewKeys: 0.002581 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:568) --- getSSHHeadersLock: 5.1e-05 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:570) --- computeDBKeys: 0.00322 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:572) --- getSshHeaders: 0.00015 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:574) --- finalizeSerialization: 0.048598 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:579) --- serializeBatch: 0.099822 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:581) --- updateSSH: 0.008117 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:583) --- serializeSubSsh: 8.6e-05 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:585) --- waitOnSSHser: 0.041361 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:589) --- waitOnWriteThread: 0.001888 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:592) --- putSSH: 0.151328 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:594) --- putSTX: 0.000495 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:597) --- getnextfeed: 22.2412 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:599) --- inControlThread: 46.3596 s
-INFO  - 1433882844: (BlockUtils.cpp:1451) --- bwbDtor: 0s
-INFO  - 1433882844: (BlockUtils.cpp:1452) Scanned Block range in 46.472s
-INFO  - 1433882844: (BlockUtils.cpp:1455) Finished loading at file 280, offset 31371188
-INFO  - 1433882844: (BlockDataViewer.cpp:155) Enabling zero-conf tracking 
-DEBUG - 1433882844: (Blockchain.cpp:214) Organizing chain 
-INFO  - 1433882844: (BlockUtils.cpp:1489) Loading block data... file 280 offset 31371188
-INFO  - 1433882844: (BlockUtils.cpp:544) Reading raw blocks finished at file 280 offset 32869610
-WARN  - 1433882844: (BlockUtils.cpp:1071) Scanning from 360193 to 360194
-WARN  - 1433882845: (BlockWriteBatcher.cpp:503) --- cumulatedBatchSleep: 0
-WARN  - 1433882845: (BlockWriteBatcher.cpp:545) --- feedSleep: 0 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:548) --- workers: 0 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:551) --- writeStxo: 0.000513 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:553) --- writeStxo_grabMutex: 6e-06 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:556) --- waitingOnSerThread: 0.00268 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:558) --- waitForDataToWrite: 0.339536 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:562) --- checkForCollisions: 4e-06 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:564) --- getExistingKeys: 0.000724 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:566) --- getNewKeys: 4e-06 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:568) --- getSSHHeadersLock: 4e-06 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:570) --- computeDBKeys: 2.7e-05 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:572) --- getSshHeaders: 1.4e-05 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:574) --- finalizeSerialization: 0.006073 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:579) --- serializeBatch: 0.001759 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:581) --- updateSSH: 0.000546 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:583) --- serializeSubSsh: 6e-06 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:585) --- waitOnSSHser: 0.005375 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:589) --- waitOnWriteThread: 5e-06 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:592) --- putSSH: 0.001174 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:594) --- putSTX: 3.7e-05 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:597) --- getnextfeed: 0.292328 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:599) --- inControlThread: 0.356495 s

Is this thread count adjustment something I can try turning off?

goatpig

legendary

Activity: 3640

Merit: 1345

Armory Developer

Gimme the part of the log where it posts the timings after the scan is over. I want to see the last block it scanned.

Roy Badami

hero member

Activity: 563

Merit: 500

Just reran it having removed the database and log files. Takes about 12 minutes to go through receiving headers, organizing blockchain and building databases - and then goes through the scan transactions phase in well under a minute (and ends up showing no transactions and 0.0 balance). I'll send you full logs of that run if you let me know the best way to get them to you.

EDIT: Block number displayed in the GUI is correct.

Roy Badami

hero member

Activity: 563

Merit: 500

Ah, after several restarts of Armory it finally started scanning - made it most of the way there - now has transactions up to late 2014. There's virtually nothing interesting in armorylog.txt.

I get the following error at startup (which I presume is largely harmless?)

Code:

2015-06-09 20:54 (INFO) -- announcefetch.py:271 - Fetching: https://bitcoinarmory.com/announce.txt
2015-06-09 20:54 (ERROR) -- announcefetch.py:312 - Could not verify data in signed message block
Traceback (most recent call last):
  File "/Users/roy/BitcoinArmory/osxbuild/workspace/Armory.app/Contents/MacOS/py/usr/lib/armory/announcefetch.py", line 304, in __runFetchSequence
    sig, msg = readSigBlock(digestData)
  File "/Users/roy/BitcoinArmory/osxbuild/workspace/Armory.app/Contents/MacOS/py/usr/lib/armory/jasvet.py", line 589, in readSigBlock
    name = r.split(BEGIN_MARKER)[1].split(DASHX5)[0]
IndexError: list index out of range

And apart from that littereally nothing of interest; just a couple of new blocks that came in during the scan:

Code:

2015-06-09 20:57 (INFO) -- ArmoryQt.py:3132 - Current block number: 360187
2015-06-09 20:57 (INFO) -- ArmoryQt.py:6235 - New Block! : 360189
2015-06-09 20:57 (INFO) -- ArmoryQt.py:6243 - Current block number: 360189
2015-06-09 20:59 (INFO) -- Networking.py:215 - Received new block.  0000000000000000141082c80
45e2baded1c074967f0fdf70fb65b3ebb55bd37
2015-06-09 20:59 (INFO) -- ArmoryQt.py:6235 - New Block! : 360190
2015-06-09 20:59 (INFO) -- ArmoryQt.py:6243 - Current block number: 360190
2015-06-09 21:04 (INFO) -- Networking.py:215 - Received new block.  00000000000000000b3c8380aab3c52af2302c8763acff016ad750c3765d7767
2015-06-09 21:04 (INFO) -- ArmoryQt.py:6235 - New Block! : 360191
2015-06-09 21:04 (INFO) -- ArmoryQt.py:6243 - Current block number: 360191
2015-06-09 21:14 (INFO) -- Networking.py:215 - Received new block.  0000000000000000144086516ccc3824128835fbef52eb26e0c0fc81723f0dac
2015-06-09 21:14 (INFO) -- ArmoryQt.py:6235 - New Block! : 360192
2015-06-09 21:14 (INFO) -- ArmoryQt.py:6243 - Current block number: 360192

EDIT: Fixed log paste

goatpig

legendary

Activity: 3640

Merit: 1345

Armory Developer

Quote from: Roy Badami on June 09, 2015, 03:01:50 PM

(On OS X)

No errors building the database - but doesn't find any transactions and all wallet balances are 0.0

EDIT: Ah, OK, database appears to build OK judging by progress, but then scanning transactions seems to complete almost instantly (so evidently it actually failed - but didn't give an error).

roy

Lemme see the last few lines of your log file. Also, what's the top block displayed in Armory?

Roy Badami

hero member

Activity: 563

Merit: 500

(On OS X)

No errors building the database - but doesn't find any transactions and all wallet balances are 0.0

EDIT: Ah, OK, database appears to build OK judging by progress, but then scanning transactions seems to complete almost instantly (so evidently it actually failed - but didn't give an error).

roy

goatpig

legendary

Activity: 3640

Merit: 1345

Armory Developer

Quote from: jl2012 on June 09, 2015, 11:20:37 AM

Quote from: goatpig on June 07, 2015, 05:31:57 PM

New version out in ffreeze, please test away. There's a wealth of robustness changes and it should also be a bit faster. However no one at Armory has experienced the issues Carlton Banks and btcchris ran into, so most of these changes were speculative. It's possible these bugs will still be there partially or in full.

As usual, looking forward to your bug reports and logs, and again thank you for the time and effort you put in helping us to test things out =)

Have you made any big change re supernode? In the previous ffreeze it did not complete even with a week. In this version it took only a few hours to complete.

Quote

I made changes to some stuff that makes supernode faster (some weird opts I should have rolled but figured it could wait for fear it would be unstable). The other issue, with pulling block data and the object lifespan remains. It's a rare occurrence but common enough to trip certain setup quite often (2 out of my 3 testers T_T). I ended rolled the optimization with the stability changes (it didn't cost that much more to add the opts at that stage)

Now I'm also convinced that the code speeding up supernode is not responsible for the instability. That gives me room to add some more optimizations (again supernode only) without fear of making bugs more convoluted (and thus harder to isolated).

Not having a clue what the issue was, I ended up fixing what you were suffering from (which was a lot more obvious than the remaining issue) in an attempt to fix the bug they are experiencing. In grand scheme of things it doesn't matter what order I fix these, since I have to go after both anyways. In the current scope, it doesn't speak so good of me since I thought I was fixing one thing and got the other instead =P

Quote

I can now get the details of a random tx with "armoryd.py gettransaction txid". I guess this means the supernode in running properly?

Not really, that just means you are using supernode indeed (which is the only the DB format now that support random txhash resolution), but that doesn't mean supernode is working per se. What you need to do to test it is to add a random bitcoin address to a wallet and getledger on the wallet, which will display that random address history along with the rest.

You can also verify this in the UI by importing some publicly known private keys to a wallet (kind of an oxymoron I know) and verify they get imported quasi instantly and that their history shows up in the main ledger.

jl2012

legendary

Activity: 1792

Merit: 1087

Quote from: goatpig on June 07, 2015, 05:31:57 PM

New version out in ffreeze, please test away. There's a wealth of robustness changes and it should also be a bit faster. However no one at Armory has experienced the issues Carlton Banks and btcchris ran into, so most of these changes were speculative. It's possible these bugs will still be there partially or in full.

As usual, looking forward to your bug reports and logs, and again thank you for the time and effort you put in helping us to test things out =)

Have you made any big change re supernode? In the previous ffreeze it did not complete even with a week. In this version it took only a few hours to complete.

I can now get the details of a random tx with "armoryd.py gettransaction txid". I guess this means the supernode in running properly?

goatpig

legendary

Activity: 3640

Merit: 1345

Armory Developer

Quote from: Carlton Banks on June 08, 2015, 05:26:33 PM

Ok this really is totally consistent behaviour. Tried not rebuilding the Db, just let it carry on from where it hits the (infinite?) loop. The headers get read again (implying the data structure for the headers wasn't committed to disk in the failed run), then it hits the same loop. I could try this with testnet I guess, but that's a fair amount of setup to confirm something so fundamental and consistent.

I've reproduced this issue and I'm on it. I've also got a clue on the other one in the process so I may get both by the next commit.

Carlton Banks

legendary

Activity: 3430

Merit: 3071

Ok this really is totally consistent behaviour. Tried not rebuilding the Db, just let it carry on from where it hits the (infinite?) loop. The headers get read again (implying the data structure for the headers wasn't committed to disk in the failed run), then it hits the same loop. I could try this with testnet I guess, but that's a fair amount of setup to confirm something so fundamental and consistent.

goatpig

legendary

Activity: 3640

Merit: 1345

Armory Developer

Quote from: Carlton Banks on June 07, 2015, 08:30:15 PM

There is a difference to my setup, in that I'm using jessie instead of wheezy, but I don't think that's the source of the problem. I know, better to keep the setup the same, but it's a long story, and 93.1 works identically on jessie as it does on wheezy.

It should work on any setup as long as the compiler is doing its job really.

Can you get through with testnet?

Carlton Banks

legendary

Activity: 3430

Merit: 3071

Quote from: goatpig on June 07, 2015, 08:14:43 PM

This is weird I didn't touch that part of the code. I'll get back to you when it's fixed (hopefully I can reproduce it)

It happens to me every time it runs. So far. (4-5 attempts)

Quote from: goatpig on June 07, 2015, 08:14:43 PM

What's the last line in the terminal?

Code:

-DEBUG - 1433717168: (Blockchain.cpp:214) Organizing chain w/ rebuild
-INFO  - 1433717171: (BlockUtils.cpp:1337) Looking for first unrecognized block
[New Thread 0x7fffd33f7700 (LWP 5367)]
[Thread 0x7fffd33f7700 (LWP 5367) exited]

Program received signal SIGTERM, Terminated.
0x00007ffff6fd050d in poll () at ../sysdeps/unix/syscall-template.S:81
81	../sysdeps/unix/syscall-template.S: No such file or directory.

The SIGTERM was generated by me, issuing a kill is the only way to get it shut down. This is consistent also.

There is a difference to my setup, in that I'm using jessie instead of wheezy, but I don't think that's the source of the problem. I know, better to keep the setup the same, but it's a long story, and 93.1 works identically on jessie as it does on wheezy.

goatpig

legendary

Activity: 3640

Merit: 1345

Armory Developer

Quote from: Carlton Banks on June 07, 2015, 07:59:23 PM

Quote from: goatpig on June 07, 2015, 07:45:30 PM

Quote from: Carlton Banks on June 07, 2015, 06:52:08 PM

Having trouble getting past this stage in the DB build:

Code:

-INFO  - 1433717171: (BlockUtils.cpp:1337) Looking for first unrecognized block

CPU cores hit the floor, that block never gets found.

Fresh DB folder? Is it maxing one core or all cores?

Yes, fresh DB. CPU activity cuts out altogether (occasional 1% blip for python). Logs and gdb output all look uninteresting.

This is weird I didn't touch that part of the code. I'll get back to you when it's fixed (hopefully I can reproduce it)

What's the last line in the terminal?

Carlton Banks

legendary

Activity: 3430

Merit: 3071

Quote from: goatpig on June 07, 2015, 07:45:30 PM

Quote from: Carlton Banks on June 07, 2015, 06:52:08 PM

Having trouble getting past this stage in the DB build:

Code:

-INFO  - 1433717171: (BlockUtils.cpp:1337) Looking for first unrecognized block

CPU cores hit the floor, that block never gets found.

Fresh DB folder? Is it maxing one core or all cores?

Yes, fresh DB. CPU activity cuts out altogether (occasional 1% blip for python). Logs and gdb output all look uninteresting.

goatpig

legendary

Activity: 3640

Merit: 1345

Armory Developer

Quote from: Carlton Banks on June 07, 2015, 06:52:08 PM

Having trouble getting past this stage in the DB build:

Code:

-INFO  - 1433717171: (BlockUtils.cpp:1337) Looking for first unrecognized block

CPU cores hit the floor, that block never gets found.

Fresh DB folder? Is it maxing one core or all cores?

Topic: Starting preliminary 0.94 testing - "Headless fullnode" - page 9. (Read 15098 times)