From 290ff49e1eb4e011cb475033e5c5c6fb1316067f Mon Sep 17 00:00:00 2001 From: Anton Evangelatov Date: Thu, 15 Mar 2018 18:37:19 +0100 Subject: [PATCH 1/6] log: see milliseconds in terminal --- log/format.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/log/format.go b/log/format.go index 0b07abb2ac..16391b65af 100644 --- a/log/format.go +++ b/log/format.go @@ -15,7 +15,7 @@ import ( const ( timeFormat = "2006-01-02T15:04:05-0700" - termTimeFormat = "01-02|15:04:05" + termTimeFormat = "01-02|15:04:05.999999" floatFormat = 'f' termMsgJust = 40 ) From b72cd7eb70ea33f56bcabce407aaec9592dcee7c Mon Sep 17 00:00:00 2001 From: Anton Evangelatov Date: Thu, 15 Mar 2018 18:18:56 +0100 Subject: [PATCH 2/6] swarm/storage: tracing for chunks --- swarm/storage/chunker.go | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/swarm/storage/chunker.go b/swarm/storage/chunker.go index 7fa7c55d24..85b9e606ee 100644 --- a/swarm/storage/chunker.go +++ b/swarm/storage/chunker.go @@ -23,6 +23,7 @@ import ( "sync" "time" + "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/metrics" ) @@ -332,6 +333,7 @@ func (self *TreeChunker) Join(key Key, chunkC chan *Chunk, depth int) LazySectio // Size is meant to be called on the LazySectionReader func (self *LazyChunkReader) Size(quitC chan bool) (n int64, err error) { + log.Debug("lazychunkreader.size", "key", self.key) if self.chunk != nil { return self.chunk.Size, nil } @@ -459,15 +461,18 @@ func (self *LazyChunkReader) join(b []byte, off int64, eoff int64, depth int, tr // block until they time out or arrive // abort if quitC is readable func retrieve(key Key, chunkC chan *Chunk, quitC chan bool) *Chunk { + log.Debug("retrieve", "key", key) chunk := NewChunk(key, nil) chunk.C = make(chan bool) // submit chunk for retrieval + log.Debug("submit chunk for retrieval", "key", key) select { case chunkC <- chunk: // submit retrieval request, someone should be listening on the other side (or we will time out globally) case <-quitC: return nil } // waiting for the chunk retrieval + log.Debug("waiting for the chunk retrieval", "key", key) select { // chunk.Size = int64(binary.LittleEndian.Uint64(chunk.SData[0:8])) case <-quitC: @@ -478,11 +483,13 @@ func retrieve(key Key, chunkC chan *Chunk, quitC chan bool) *Chunk { if len(chunk.SData) == 0 { return nil } + log.Debug("chunk retrieved", "key", key) return chunk } // Read keeps a cursor so cannot be called simulateously, see ReadAt func (self *LazyChunkReader) Read(b []byte) (read int, err error) { + log.Debug("lazychunkreader.read", "key", self.key) read, err = self.ReadAt(b, self.off) self.off += int64(read) @@ -494,6 +501,7 @@ var errWhence = errors.New("Seek: invalid whence") var errOffset = errors.New("Seek: invalid offset") func (s *LazyChunkReader) Seek(offset int64, whence int) (int64, error) { + log.Debug("lazychunkreader.seek", "key", s.key, "offset", offset) switch whence { default: return 0, errWhence From 4ffd38efb7b590e967e025c5f4aa5c00db7654f5 Mon Sep 17 00:00:00 2001 From: Anton Evangelatov Date: Thu, 15 Mar 2018 19:04:28 +0100 Subject: [PATCH 3/6] swarm/storage: tracing for chunk --- swarm/storage/ldbstore.go | 11 ++++++++--- swarm/storage/localstore.go | 1 + swarm/storage/memstore.go | 2 ++ 3 files changed, 11 insertions(+), 3 deletions(-) diff --git a/swarm/storage/ldbstore.go b/swarm/storage/ldbstore.go index 8bc080c1ba..6619a02d5b 100644 --- a/swarm/storage/ldbstore.go +++ b/swarm/storage/ldbstore.go @@ -546,6 +546,7 @@ func (s *LDBStore) CurrentStorageIndex() uint64 { } func (s *LDBStore) Put(chunk *Chunk) { + log.Trace("ldbstore.put", "key", chunk.Key) ikey := getIndexKey(chunk.Key) var index dpaDBIndex @@ -553,6 +554,7 @@ func (s *LDBStore) Put(chunk *Chunk) { s.lock.Lock() defer s.lock.Unlock() + log.Trace("ldbstore.put: s.db.Get", "key", chunk.Key) idata, err := s.db.Get(ikey) if err != nil { s.doPut(chunk, ikey, &index, po) @@ -562,7 +564,7 @@ func (s *LDBStore) Put(chunk *Chunk) { close(chunk.dbStored) }() } else { - log.Trace(fmt.Sprintf("DbStore: chunk already exists, only update access")) + log.Trace("ldbstore.put: chunk already exists, only update access", "key", chunk.Key) decodeIndex(idata, &index) close(chunk.dbStored) } @@ -578,6 +580,7 @@ func (s *LDBStore) Put(chunk *Chunk) { // force putting into db, does not check access index func (s *LDBStore) doPut(chunk *Chunk, ikey []byte, index *dpaDBIndex, po uint8) { + log.Trace("ldbstore.doPut", "key", chunk.Key) data := s.encodeDataFunc(chunk) s.batch.Put(getDataKey(s.dataIdx, po), data) index.Idx = s.dataIdx @@ -659,6 +662,7 @@ func (s *LDBStore) tryAccessIdx(ikey []byte, index *dpaDBIndex) bool { } func (s *LDBStore) Get(key Key) (chunk *Chunk, err error) { + //log.Trace("ldbstore.get", "key", chunk.Key) - seems like chunk is nil sometimes s.lock.Lock() defer s.lock.Unlock() return s.get(key) @@ -671,6 +675,7 @@ func (s *LDBStore) get(key Key) (chunk *Chunk, err error) { var data []byte if s.getDataFunc != nil { // if getDataFunc is defined, use it to retrieve the chunk data + log.Trace("ldbstore.get retrieve with getDataFunc", "key", key) data, err = s.getDataFunc(key) if err != nil { return @@ -680,9 +685,9 @@ func (s *LDBStore) get(key Key) (chunk *Chunk, err error) { proximity := s.po(key) datakey := getDataKey(indx.Idx, proximity) data, err = s.db.Get(datakey) - log.Trace(fmt.Sprintf("DBStore: Chunk %v indexkey %v datakey %x proximity %d", key.Log(), indx.Idx, datakey, proximity)) + log.Trace("ldbstore.get retrieve", "key", key, "indexkey", indx.Idx, "datakey", datakey, "proximity", proximity) if err != nil { - log.Trace(fmt.Sprintf("DBStore: Chunk %v found but could not be accessed: %v", key.Log(), err)) + log.Trace("ldbstore.get chunk found but could not be accessed", "key", key, "err", err) s.delete(indx.Idx, getIndexKey(key), s.po(key)) return } diff --git a/swarm/storage/localstore.go b/swarm/storage/localstore.go index 1f38d518b6..d0fe062795 100644 --- a/swarm/storage/localstore.go +++ b/swarm/storage/localstore.go @@ -85,6 +85,7 @@ func (self *LocalStore) CacheCounter() uint64 { // LocalStore is itself a chunk store // unsafe, in that the data is not integrity checked func (self *LocalStore) Put(chunk *Chunk) { + log.Trace("localstore.put", "key", chunk.Key) self.mu.Lock() defer self.mu.Unlock() diff --git a/swarm/storage/memstore.go b/swarm/storage/memstore.go index ead9412b62..7f7c282dc4 100644 --- a/swarm/storage/memstore.go +++ b/swarm/storage/memstore.go @@ -144,6 +144,7 @@ func (s *MemStore) Counter() uint { // entry (not its copy) is going to be in MemStore func (s *MemStore) Put(entry *Chunk) { + log.Trace("memstore.put", "key", entry.Key) if s.capacity == 0 { return } @@ -219,6 +220,7 @@ func (s *MemStore) Put(entry *Chunk) { } func (s *MemStore) Get(hash Key) (chunk *Chunk, err error) { + log.Trace("memstore.get", "key", hash) s.lock.Lock() defer s.lock.Unlock() From 61ffbbbe7873d7caafe4998095f86bd36e44b8db Mon Sep 17 00:00:00 2001 From: Anton Evangelatov Date: Thu, 22 Mar 2018 14:55:25 +0100 Subject: [PATCH 4/6] swarm/storage: close dbStored when we are retrieving from LevelDB --- swarm/storage/ldbstore.go | 1 + swarm/storage/memstore.go | 10 ++++++---- 2 files changed, 7 insertions(+), 4 deletions(-) diff --git a/swarm/storage/ldbstore.go b/swarm/storage/ldbstore.go index 6619a02d5b..e79d0f918a 100644 --- a/swarm/storage/ldbstore.go +++ b/swarm/storage/ldbstore.go @@ -707,6 +707,7 @@ func (s *LDBStore) get(key Key) (chunk *Chunk, err error) { } chunk = NewChunk(key, nil) + close(chunk.dbStored) decodeData(data, chunk) } else { err = ErrChunkNotFound diff --git a/swarm/storage/memstore.go b/swarm/storage/memstore.go index 7f7c282dc4..5a1ff04c57 100644 --- a/swarm/storage/memstore.go +++ b/swarm/storage/memstore.go @@ -230,6 +230,7 @@ func (s *MemStore) Get(hash Key) (chunk *Chunk, err error) { l := hash.bits(bitpos, node.bits) st := node.subtree[l] if st == nil { + log.Trace("memstore.get ErrChunkNotFound", "key", hash) return nil, ErrChunkNotFound } bitpos += node.bits @@ -251,6 +252,7 @@ func (s *MemStore) Get(hash Key) (chunk *Chunk, err error) { err = ErrChunkNotFound } + log.Trace("memstore.get return", "key", hash, "chunk", chunk, "err", err) return } @@ -298,11 +300,11 @@ func (s *MemStore) removeOldest() { } - log.Trace(fmt.Sprintf("Memstore Clean: Waiting for chunk %v to be saved", node.entry.Key.Log())) - <-node.entry.dbStored - log.Trace(fmt.Sprintf("Memstore Clean: Chunk %v saved to DBStore. Ready to clear from mem.", node.entry.Key.Log())) - if node.entry.ReqC == nil { + log.Trace(fmt.Sprintf("Memstore Clean: Waiting for chunk %v to be saved", node.entry.Key.Log())) + <-node.entry.dbStored + log.Trace(fmt.Sprintf("Memstore Clean: Chunk %v saved to DBStore. Ready to clear from mem.", node.entry.Key.Log())) + memstoreRemoveCounter.Inc(1) node.entry = nil s.entryCnt-- From f03c58336b747a7b4ec22b4d6d2845e0f5533123 Mon Sep 17 00:00:00 2001 From: Anton Evangelatov Date: Fri, 23 Mar 2018 17:31:03 +0100 Subject: [PATCH 5/6] swarm/storage: remove redundant trace --- swarm/storage/pyramid.go | 2 -- 1 file changed, 2 deletions(-) diff --git a/swarm/storage/pyramid.go b/swarm/storage/pyramid.go index 670194205c..4fa46a69c6 100644 --- a/swarm/storage/pyramid.go +++ b/swarm/storage/pyramid.go @@ -266,8 +266,6 @@ func (self *PyramidChunker) processor(id int64, jobC chan *chunkJob, chunkC chan } func (self *PyramidChunker) processChunk(id int64, hasher SwarmHash, job *chunkJob, chunkC chan *Chunk, storageWG *sync.WaitGroup) { - log.Debug("pyramid.chunker: processChunk()", "id", id) - hasher.ResetWithLength(job.chunk[:8]) // 8 bytes of length hasher.Write(job.chunk[8:]) // minus 8 []byte length h := hasher.Sum(nil) From a1b2b4c5b691dcafc2abbefbbcae205b7159daf6 Mon Sep 17 00:00:00 2001 From: Anton Evangelatov Date: Fri, 23 Mar 2018 21:25:04 +0100 Subject: [PATCH 6/6] swarm/storage: fixed comment and improved error. cleandb no longer exists --- swarm/storage/ldbstore.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/swarm/storage/ldbstore.go b/swarm/storage/ldbstore.go index e79d0f918a..e60b0fc522 100644 --- a/swarm/storage/ldbstore.go +++ b/swarm/storage/ldbstore.go @@ -662,7 +662,7 @@ func (s *LDBStore) tryAccessIdx(ikey []byte, index *dpaDBIndex) bool { } func (s *LDBStore) Get(key Key) (chunk *Chunk, err error) { - //log.Trace("ldbstore.get", "key", chunk.Key) - seems like chunk is nil sometimes + log.Trace("ldbstore.get", "key", key) s.lock.Lock() defer s.lock.Unlock() return s.get(key) @@ -700,9 +700,9 @@ func (s *LDBStore) get(key Key) (chunk *Chunk, err error) { hash := hasher.Sum(nil) if !bytes.Equal(hash, key) { - log.Error(fmt.Sprintf("Apparent key/hash mismatch. Hash %x, key %v", hash, key[:])) + log.Error("apparent key/hash mismatch", "hash", hash, "key", key[:]) s.delete(indx.Idx, getIndexKey(key), s.po(key)) - log.Error("Invalid Chunk in Database. Please repair with command: 'swarm cleandb'") + log.Error("invalid chunk in database.") } }