Why are the rpc calls getting slow?

Question

I am using multichain to run a node on a single machine. Along with that there is a script running every minute making transaction in the block chain. The issue is that after running for a few days , the rpc calls have become painstakingly slow.
The instance was running on a remote machine initially with 2gb of ram. I upgraded the RAM to 8gb and still not much difference.

I was running version 1.0 alpha 29 for linux. I upgraded the version to 1.0 beta 2. The rpc-api speed increased marginally however it is still pretty slow.

Almost every api takes more than 10-15 seconds.

Can anyone please suggest a solution to this.

Comments

I shall mail you the files. In the meantime I'll try the reindex option and changing the conf with txindex=1 and server=1 like in bitcoin before restarting and will also check the debug logs.

---

Thanks for sending the files. We brought your blockchain (with 22459 blocks) up under MultiChain 1.0 beta 2 on Ubuntu 14.04.5 LTS and saw no issues. It used 0.3% CPU and 50 MB of memory, and API calls received immediate responses. If you bring the node down (using the stop API command) then back up again, do you immediately see this slow behavior, or does it take some time to appear? If the effect is immediate it has to be related to something else on this system, since we don't see that effect ourselves.

---

BTW might you be calling listassets repeatedly in your script? If so and you're passing verbose=true, this will cause a lot of load, because that is a very big (11 MB) JSON-RPC response. Even with verbose=false it can take a second, because this asset has over 30,000 follow-on issuance events.

---

Apart from the three apis I mentioned earlier with the timings, I only use issuemore. Basically just 4 rpcs.
Thanks a lot for helping, I'll try to debug more and update it once I find some solution.

---

You also might want to try transferring it to a new server instance (just install the blockchain directory then launch multichaind like usual). Perhaps there is some networking issue on that particular one.

Answer 1

The problem is almost definitely that you are sending transactions from the node back to itself, and this is inflating the number of unspent transaction outputs (UTXOs) in its wallet – each transaction spends one output and creates two. This in turn slows down the procedure by which the wallet selects which previous UTXOs it should spend. There are a few workarounds for this problem:

• Use the combineunspent API (or set up auto combination in the runtime parameters). This requires the address with many UTXOs to have both send and receive permissions.
• Send the coins to an address not tracked by the wallet, e.g. the chain's burnaddress (from getinfo).
• If your only purpose is testing, send a transaction with only one spendable output. For example it can be a publish transaction.

Comments

I am sorry I did not mention that the addresses I am making the transactions to are generated by using createkeypairs , so the wallet has only the one address which was generated when multichain is initialised. Also the UTXO obtained by executing listunspent has only one transaction.
To elucidate more on the script which makes transactions, it generates 80-120 addresses on a daily basis(using createkeypairs) and grants permission to send and receive.
Every minute it makes 6 transactions which are issuemore txs with the address being any one from the ones described above.
Also only one asset is being used.

---

Understood. Then this is indeed strange behavior. Have you tried performing a single transaction manually using multichain-cli on the same server where the node is running? That would rule out any issue with latency or in your own test code.

---

The script is running (as an every minute cron) on the remote server itself hitting localhost at the respective port.  I wrote a test script to get the timings each rpc is taking. The test has 3 rpcs 1. createkeypairs 2. grant send,receive and 3. issuemore.
The timings i got are as follows(in seconds):
createkeypair time  30.7139589787
grant time  40.4964780807
issue time  36.2183480263

I stopped the crons and executed the same script again, in case the crons were flooding the daemon with rpc calls. But still, the time taken was the same.

createkeypair time  40.6067891121
grant time  48.307849884
issue time  32.8067090511

---

Thanks. The createkeypairs call doesn't even interact with the wallet or node, so this is some general issue with the API's performance. Have you checked for general issues on that server and to see the memory/CPU using of MultiChain using tools like top, free, vmstat?

---

multichaind is using 95-120% cpu on a quadcore and 2-5% ram.
4GB of the 8GB is free. So the system is running pretty smoothly. Its only multichain which is having an issue.

---

Is it possible the node is mining very CPU intensive blocks? Can you post getblockchainparams please, as well as the output of listblocks -5.

---

getblockchainparams

{
    "chain-protocol" : "multichain",
    "chain-description" : "MultiChain chain1",
    "root-stream-name" : "root",
    "root-stream-open" : true,
    "chain-is-testnet" : false,
    "target-block-time" : 15,
    "maximum-block-size" : 8388608,
    "default-network-port" : 4329,
    "default-rpc-port" : 8372,
    "anyone-can-connect" : false,
    "anyone-can-send" : false,
    "anyone-can-receive" : false,
    "anyone-can-receive-empty" : true,
    "anyone-can-create" : false,
    "anyone-can-issue" : false,
    "anyone-can-mine" : false,
    "anyone-can-activate" : false,
    "anyone-can-admin" : false,
    "support-miner-precheck" : true,
    "allow-p2sh-outputs" : true,
    "allow-multisig-outputs" : true,
    "setup-first-blocks" : 60,
    "mining-diversity" : 0.30000000,
    "admin-consensus-upgrade" : 0.50000000,
    "admin-consensus-admin" : 0.50000000,
    "admin-consensus-activate" : 0.50000000,
    "admin-consensus-mine" : 0.50000000,
    "admin-consensus-create" : 0.00000000,
    "admin-consensus-issue" : 0.00000000,
    "lock-admin-mine-rounds" : 10,
    "mining-requires-peers" : true,
    "mine-empty-rounds" : 10.00000000,
    "mining-turnover" : 0.50000000,
    "first-block-reward" : -1,
    "initial-block-reward" : 0,
    "reward-halving-interval" : 52560000,
    "reward-spendable-delay" : 1,
    "minimum-per-output" : 0,
    "maximum-per-output" : 100000000000000,
    "minimum-relay-fee" : 0,
    "native-currency-multiple" : 100000000,
    "skip-pow-check" : false,
    "pow-minimum-bits" : 8,
    "target-adjust-freq" : -1,
    "allow-min-difficulty-blocks" : false,
    "only-accept-std-txs" : true,
    "max-std-tx-size" : 4194304,
    "max-std-op-returns-count" : 10,
    "max-std-op-return-size" : 2097152,
    "max-std-op-drops-count" : 5,
    "max-std-element-size" : 8192,
    "chain-name" : "chain1",
    "protocol-version" : 10008,
    "network-message-start" : "f6eeebf5",
    "address-pubkeyhash-version" : "00b75825",
    "address-scripthash-version" : "057fa059",
    "private-key-version" : "80ae002e",
    "address-checksum-value" : "a0dcaf3f",
    "genesis-pubkey" : "03c8fde54ed78cb4b1e04059013628ef7bdd807b52a3a225c337d5f6afc99de5c7",
    "genesis-version" : 1,
    "genesis-timestamp" : 1498811247,
    "genesis-nbits" : 536936447,
    "genesis-nonce" : 151,
    "genesis-pubkey-hash" : "95a8e4ce385a66bdadec205624d67be677558d8e",
    "genesis-hash" : "00b653886c575ecdf3c9922efdae4c5ed6e6575a688b510bbb2ed6794cc78ca1",
    "chain-params-hash" : "9a366692f2f7ed9dfac66eb3edbe62797a2723cc3bba17668349bc87aa7da3aa"
}


listblocks -5

[
    {
        "hash" : "001e0942e594d6107d34afee5af99753efe0fef59892c9c86578cd77d22b4270",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 5,
        "height" : 22455,
        "time" : 1499158794,
        "txcount" : 1
    },
    {
        "hash" : "0043e6f12cf6f84f57d66947382f4e60f2b56b1cadbaf53e644dba40c9a3b656",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 4,
        "height" : 22456,
        "time" : 1499158814,
        "txcount" : 1
    },
    {
        "hash" : "008c40f575533d29f6b607eb9f5617a4263706f300bd74b5675db8ccdff08451",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 3,
        "height" : 22457,
        "time" : 1499158826,
        "txcount" : 1
    },
    {
        "hash" : "00a13a6bf5f61b91136fd957fbce4d2b3832b6df44316075a4d221b78adf87be",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 2,
        "height" : 22458,
        "time" : 1499158844,
        "txcount" : 1
    },
    {
        "hash" : "00cd5dc73d08bcbf85f0898b59df6d65b8f688a304da7eab7b44b5052efb80b0",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 1,
        "height" : 22459,
        "time" : 1499158863,
        "txcount" : 1
    }
]


listblocks -15
[
    {
        "hash" : "00eaf16c620e4ec05a578f14ac68cede14d750de166b31e056f40b609b6664ae",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 15,
        "height" : 22445,
        "time" : 1499158606,
        "txcount" : 2
    },
    {
        "hash" : "00546f32e6bb4a05ed3f251de90b0e5ee08453c700b8993c7f94e08949a8461f",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 14,
        "height" : 22446,
        "time" : 1499158627,
        "txcount" : 2
    },
    {
        "hash" : "0068907e4a77870b50506aa88a6b27ae4125ec1a3233d137f5c08b86dd097450",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 13,
        "height" : 22447,
        "time" : 1499158648,
        "txcount" : 2
    },
    {
        "hash" : "00d07ab46c3f6ac7a07f1e6dcf104b10c9de4dc882e8ba75a4957c85ec89fe78",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 12,
        "height" : 22448,
        "time" : 1499158665,
        "txcount" : 1
    },
    {
        "hash" : "00fb5beb4c2a23fdd711ae297ce19a8f876997bda781901c810b70a327d378ed",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 11,
        "height" : 22449,
        "time" : 1499158686,
        "txcount" : 2
    },
    {
        "hash" : "0041bf88eec0987946084f28260735f0a028eb7f7280b16e60df6c9a2dc535dc",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 10,
        "height" : 22450,
        "time" : 1499158706,
        "txcount" : 1
    },
    {
        "hash" : "00dea593798cc544548a4dec38a09251050516de4fe8754a1ffa96bba500363a",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 9,
        "height" : 22451,
        "time" : 1499158728,
        "txcount" : 1
    },
    {
        "hash" : "00f6bfad78e3207c36c1a2623784d1bc48c02219f2d79b746bb39d7ee8de0c94",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 8,
        "height" : 22452,
        "time" : 1499158746,
        "txcount" : 1
    },
    {
        "hash" : "001b338bb7de0890d0810fa48db01b0b124546e902eaba18707d0a47579967fb",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 7,
        "height" : 22453,
        "time" : 1499158759,
        "txcount" : 1
    },
    {
        "hash" : "00a9adba6b0b4dfdcff6f03003054fc9fc6dc22ab33adfe753e2296d89483f09",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 6,
        "height" : 22454,
        "time" : 1499158777,
        "txcount" : 1
    },
    {
        "hash" : "001e0942e594d6107d34afee5af99753efe0fef59892c9c86578cd77d22b4270",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 5,
        "height" : 22455,
        "time" : 1499158794,
        "txcount" : 1
    },
    {
        "hash" : "0043e6f12cf6f84f57d66947382f4e60f2b56b1cadbaf53e644dba40c9a3b656",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 4,
        "height" : 22456,
        "time" : 1499158814,
        "txcount" : 1
    },
    {
        "hash" : "008c40f575533d29f6b607eb9f5617a4263706f300bd74b5675db8ccdff08451",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 3,
        "height" : 22457,
        "time" : 1499158826,
        "txcount" : 1
    },
    {
        "hash" : "00a13a6bf5f61b91136fd957fbce4d2b3832b6df44316075a4d221b78adf87be",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 2,
        "height" : 22458,
        "time" : 1499158844,
        "txcount" : 1
    },
    {
        "hash" : "00cd5dc73d08bcbf85f0898b59df6d65b8f688a304da7eab7b44b5052efb80b0",
        "miner" : "1MEBPTVRfa36dJmYj7V28KhRnGm8qQPZ2YYnXZ",
        "confirmations" : 1,
        "height" : 22459,
        "time" : 1499158863,
        "txcount" : 1
    }
]



all blocks have not more than 15-20 txs in them

---

Thanks. The mystery is not yet solved. I presume that if you stop the node and bring it back up again, the problem persists - since you already upgraded your version of MultiChain.

Would you be willing to stop your node and send your blockchain directory to us at multichain dot debug at gmail dot com? We could then take a look and try to figure it out.

If you prefer not to do that, please try stopping the node then restarting with the -reindex flag on the command line.

You could also take a look at the last 10000 lines in the debug.log file to see if there's any hint as to what MultiChain is burning CPU cycles on.